granicus.if.org Git - postgresql/blob - src/backend/postmaster/syslogger.c

   1 /*-------------------------------------------------------------------------
   2  *
   3  * syslogger.c
   4  *
   5  * The system logger (syslogger) is new in Postgres 8.0. It catches all
   6  * stderr output from the postmaster, backends, and other subprocesses
   7  * by redirecting to a pipe, and writes it to a set of logfiles.
   8  * It's possible to have size and age limits for the logfile configured
   9  * in postgresql.conf. If these limits are reached or passed, the
  10  * current logfile is closed and a new one is created (rotated).
  11  * The logfiles are stored in a subdirectory (configurable in
  12  * postgresql.conf), using an internal naming scheme that mangles
  13  * creation time and current postmaster pid.
  14  *
  15  * Author: Andreas Pflug <pgadmin@pse-consulting.de>
  16  *
  17  * Copyright (c) 2004-2007, PostgreSQL Global Development Group
  18  *
  19  *
  20  * IDENTIFICATION
  21  *        $PostgreSQL: pgsql/src/backend/postmaster/syslogger.c,v 1.41 2007/11/15 21:14:37 momjian Exp $
  22  *
  23  *-------------------------------------------------------------------------
  24  */
  25 #include "postgres.h"
  26
  27 #include <fcntl.h>
  28 #include <signal.h>
  29 #include <time.h>
  30 #include <unistd.h>
  31 #include <sys/stat.h>
  32 #include <sys/time.h>
  33
  34 #include "lib/stringinfo.h"
  35 #include "libpq/pqsignal.h"
  36 #include "miscadmin.h"
  37 #include "pgtime.h"
  38 #include "postmaster/fork_process.h"
  39 #include "postmaster/postmaster.h"
  40 #include "postmaster/syslogger.h"
  41 #include "storage/ipc.h"
  42 #include "storage/pg_shmem.h"
  43 #include "utils/guc.h"
  44 #include "utils/ps_status.h"
  45 #include "utils/timestamp.h"
  46
  47 /*
  48  * We really want line-buffered mode for logfile output, but Windows does
  49  * not have it, and interprets _IOLBF as _IOFBF (bozos).  So use _IONBF
  50  * instead on Windows.
  51  */
  52 #ifdef WIN32
  53 #define LBF_MODE        _IONBF
  54 #else
  55 #define LBF_MODE        _IOLBF
  56 #endif
  57
  58 /*
  59  * We read() into a temp buffer twice as big as a chunk, so that any fragment
  60  * left after processing can be moved down to the front and we'll still have
  61  * room to read a full chunk.
  62  */
  63 #define READ_BUF_SIZE (2 * PIPE_CHUNK_SIZE)
  64
  65
  66 /*
  67  * GUC parameters.      Logging_collector cannot be changed after postmaster
  68  * start, but the rest can change at SIGHUP.
  69  */
  70 bool            Logging_collector = false;
  71 int                     Log_RotationAge = HOURS_PER_DAY * MINS_PER_HOUR;
  72 int                     Log_RotationSize = 10 * 1024;
  73 char       *Log_directory = NULL;
  74 char       *Log_filename = NULL;
  75 bool            Log_truncate_on_rotation = false;
  76
  77 /*
  78  * Globally visible state (used by elog.c)
  79  */
  80 bool            am_syslogger = false;
  81
  82 extern bool redirection_done;
  83
  84 /*
  85  * Private state
  86  */
  87 static pg_time_t next_rotation_time;
  88 static bool pipe_eof_seen = false;
  89 static FILE *syslogFile = NULL;
  90 static FILE *csvlogFile = NULL;
  91 static char *last_file_name = NULL;
  92 static char *last_csvfile_name = NULL;
  93
  94 /*
  95  * Buffers for saving partial messages from different backends. We don't expect
  96  * that there will be very many outstanding at one time, so 20 seems plenty of
  97  * leeway. If this array gets full we won't lose messages, but we will lose
  98  * the protocol protection against them being partially written or interleaved.
  99  *
 100  * An inactive buffer has pid == 0 and undefined contents of data.
 101  */
 102 typedef struct
 103 {
 104         int32           pid;                    /* PID of source process */
 105         StringInfoData data;            /* accumulated data, as a StringInfo */
 106 }       save_buffer;
 107
 108 #define CHUNK_SLOTS 20
 109 static save_buffer saved_chunks[CHUNK_SLOTS];
 110
 111 /* These must be exported for EXEC_BACKEND case ... annoying */
 112 #ifndef WIN32
 113 int                     syslogPipe[2] = {-1, -1};
 114 #else
 115 HANDLE          syslogPipe[2] = {0, 0};
 116 #endif
 117
 118 #ifdef WIN32
 119 static HANDLE threadHandle = 0;
 120 static CRITICAL_SECTION sysfileSection;
 121 #endif
 122
 123 /*
 124  * Flags set by interrupt handlers for later service in the main loop.
 125  */
 126 static volatile sig_atomic_t got_SIGHUP = false;
 127 static volatile sig_atomic_t rotation_requested = false;
 128
 129
 130 /* Local subroutines */
 131 #ifdef EXEC_BACKEND
 132 static pid_t syslogger_forkexec(void);
 133 static void syslogger_parseArgs(int argc, char *argv[]);
 134 #endif
 135 static void process_pipe_input(char *logbuffer, int *bytes_in_logbuffer);
 136 static void flush_pipe_input(char *logbuffer, int *bytes_in_logbuffer);
 137 static void open_csvlogfile(void);
 138
 139 #ifdef WIN32
 140 static unsigned int __stdcall pipeThread(void *arg);
 141 #endif
 142 static void logfile_rotate(bool time_based_rotation, int size_rotation_for);
 143 static char *logfile_getname(pg_time_t timestamp, char *suffix);
 144 static void set_next_rotation_time(void);
 145 static void sigHupHandler(SIGNAL_ARGS);
 146 static void sigUsr1Handler(SIGNAL_ARGS);
 147
 148
 149 /*
 150  * Main entry point for syslogger process
 151  * argc/argv parameters are valid only in EXEC_BACKEND case.
 152  */
 153 NON_EXEC_STATIC void
 154 SysLoggerMain(int argc, char *argv[])
 155 {
 156 #ifndef WIN32
 157         char            logbuffer[READ_BUF_SIZE];
 158         int                     bytes_in_logbuffer = 0;
 159 #endif
 160         char       *currentLogDir;
 161         char       *currentLogFilename;
 162         int                     currentLogRotationAge;
 163
 164         IsUnderPostmaster = true;       /* we are a postmaster subprocess now */
 165
 166         MyProcPid = getpid();           /* reset MyProcPid */
 167
 168         MyStartTime = time(NULL);       /* set our start time in case we call elog */
 169
 170 #ifdef EXEC_BACKEND
 171         syslogger_parseArgs(argc, argv);
 172 #endif   /* EXEC_BACKEND */
 173
 174         am_syslogger = true;
 175
 176         init_ps_display("logger process", "", "", "");
 177
 178         /*
 179          * If we restarted, our stderr is already redirected into our own input
 180          * pipe.  This is of course pretty useless, not to mention that it
 181          * interferes with detecting pipe EOF.  Point stderr to /dev/null. This
 182          * assumes that all interesting messages generated in the syslogger will
 183          * come through elog.c and will be sent to write_syslogger_file.
 184          */
 185         if (redirection_done)
 186         {
 187                 int                     fd = open(NULL_DEV, O_WRONLY, 0);
 188
 189                 /*
 190                  * The closes might look redundant, but they are not: we want to be
 191                  * darn sure the pipe gets closed even if the open failed.      We can
 192                  * survive running with stderr pointing nowhere, but we can't afford
 193                  * to have extra pipe input descriptors hanging around.
 194                  */
 195                 close(fileno(stdout));
 196                 close(fileno(stderr));
 197                 dup2(fd, fileno(stdout));
 198                 dup2(fd, fileno(stderr));
 199                 close(fd);
 200         }
 201
 202         /*
 203          * Syslogger's own stderr can't be the syslogPipe, so set it back to text
 204          * mode if we didn't just close it. (It was set to binary in
 205          * SubPostmasterMain).
 206          */
 207 #ifdef WIN32
 208         else
 209                 _setmode(_fileno(stderr), _O_TEXT);
 210 #endif
 211
 212         /*
 213          * Also close our copy of the write end of the pipe.  This is needed to
 214          * ensure we can detect pipe EOF correctly.  (But note that in the restart
 215          * case, the postmaster already did this.)
 216          */
 217 #ifndef WIN32
 218         if (syslogPipe[1] >= 0)
 219                 close(syslogPipe[1]);
 220         syslogPipe[1] = -1;
 221 #else
 222         if (syslogPipe[1])
 223                 CloseHandle(syslogPipe[1]);
 224         syslogPipe[1] = 0;
 225 #endif
 226
 227         /*
 228          * If possible, make this process a group leader, so that the postmaster
 229          * can signal any child processes too.  (syslogger probably never has any
 230          * child processes, but for consistency we make all postmaster child
 231          * processes do this.)
 232          */
 233 #ifdef HAVE_SETSID
 234         if (setsid() < 0)
 235                 elog(FATAL, "setsid() failed: %m");
 236 #endif
 237
 238         /*
 239          * Properly accept or ignore signals the postmaster might send us
 240          *
 241          * Note: we ignore all termination signals, and instead exit only when all
 242          * upstream processes are gone, to ensure we don't miss any dying gasps of
 243          * broken backends...
 244          */
 245
 246         pqsignal(SIGHUP, sigHupHandler);        /* set flag to read config file */
 247         pqsignal(SIGINT, SIG_IGN);
 248         pqsignal(SIGTERM, SIG_IGN);
 249         pqsignal(SIGQUIT, SIG_IGN);
 250         pqsignal(SIGALRM, SIG_IGN);
 251         pqsignal(SIGPIPE, SIG_IGN);
 252         pqsignal(SIGUSR1, sigUsr1Handler);      /* request log rotation */
 253         pqsignal(SIGUSR2, SIG_IGN);
 254
 255         /*
 256          * Reset some signals that are accepted by postmaster but not here
 257          */
 258         pqsignal(SIGCHLD, SIG_DFL);
 259         pqsignal(SIGTTIN, SIG_DFL);
 260         pqsignal(SIGTTOU, SIG_DFL);
 261         pqsignal(SIGCONT, SIG_DFL);
 262         pqsignal(SIGWINCH, SIG_DFL);
 263
 264         PG_SETMASK(&UnBlockSig);
 265
 266 #ifdef WIN32
 267         /* Fire up separate data transfer thread */
 268         InitializeCriticalSection(&sysfileSection);
 269
 270         {
 271                 unsigned int tid;
 272
 273                 threadHandle = (HANDLE) _beginthreadex(0, 0, pipeThread, 0, 0, &tid);
 274         }
 275 #endif   /* WIN32 */
 276
 277         /* remember active logfile parameters */
 278         currentLogDir = pstrdup(Log_directory);
 279         currentLogFilename = pstrdup(Log_filename);
 280         currentLogRotationAge = Log_RotationAge;
 281         /* set next planned rotation time */
 282         set_next_rotation_time();
 283
 284         /* main worker loop */
 285         for (;;)
 286         {
 287                 bool            time_based_rotation = false;
 288                 int                     size_rotation_for = 0;
 289
 290 #ifndef WIN32
 291                 int                     bytesRead;
 292                 int                     rc;
 293                 fd_set          rfds;
 294                 struct timeval timeout;
 295 #endif
 296
 297                 if (got_SIGHUP)
 298                 {
 299                         got_SIGHUP = false;
 300                         ProcessConfigFile(PGC_SIGHUP);
 301
 302                         /*
 303                          * Check if the log directory or filename pattern changed in
 304                          * postgresql.conf. If so, force rotation to make sure we're
 305                          * writing the logfiles in the right place.
 306                          */
 307                         if (strcmp(Log_directory, currentLogDir) != 0)
 308                         {
 309                                 pfree(currentLogDir);
 310                                 currentLogDir = pstrdup(Log_directory);
 311                                 rotation_requested = true;
 312                         }
 313                         if (strcmp(Log_filename, currentLogFilename) != 0)
 314                         {
 315                                 pfree(currentLogFilename);
 316                                 currentLogFilename = pstrdup(Log_filename);
 317                                 rotation_requested = true;
 318                         }
 319
 320                         /*
 321                          * If rotation time parameter changed, reset next rotation time,
 322                          * but don't immediately force a rotation.
 323                          */
 324                         if (currentLogRotationAge != Log_RotationAge)
 325                         {
 326                                 currentLogRotationAge = Log_RotationAge;
 327                                 set_next_rotation_time();
 328                         }
 329                 }
 330
 331                 if (!rotation_requested && Log_RotationAge > 0)
 332                 {
 333                         /* Do a logfile rotation if it's time */
 334                         pg_time_t       now = time(NULL);
 335
 336                         if (now >= next_rotation_time)
 337                                 rotation_requested = time_based_rotation = true;
 338                 }
 339
 340                 if (!rotation_requested && Log_RotationSize > 0)
 341                 {
 342                         /* Do a rotation if file is too big */
 343                         if (ftell(syslogFile) >= Log_RotationSize * 1024L)
 344                         {
 345                                 rotation_requested = true;
 346                                 size_rotation_for |= LOG_DESTINATION_STDERR;
 347                         }
 348                         if (csvlogFile != NULL && ftell(csvlogFile) >= Log_RotationSize * 1024L)
 349                         {
 350                                 rotation_requested = true;
 351                                 size_rotation_for |= LOG_DESTINATION_CSVLOG;
 352                         }
 353
 354                 }
 355
 356                 if (rotation_requested)
 357                 {
 358                         /*
 359                          * Force rotation when both values are zero. It means the request
 360                          * was sent by pg_rotate_logfile.
 361                          */
 362                         if (!time_based_rotation && size_rotation_for == 0)
 363                                 size_rotation_for = LOG_DESTINATION_STDERR | LOG_DESTINATION_CSVLOG;
 364                         logfile_rotate(time_based_rotation, size_rotation_for);
 365                 }
 366
 367 #ifndef WIN32
 368
 369                 /*
 370                  * Wait for some data, timing out after 1 second
 371                  */
 372                 FD_ZERO(&rfds);
 373                 FD_SET(syslogPipe[0], &rfds);
 374                 timeout.tv_sec = 1;
 375                 timeout.tv_usec = 0;
 376
 377                 rc = select(syslogPipe[0] + 1, &rfds, NULL, NULL, &timeout);
 378
 379                 if (rc < 0)
 380                 {
 381                         if (errno != EINTR)
 382                                 ereport(LOG,
 383                                                 (errcode_for_socket_access(),
 384                                                  errmsg("select() failed in logger process: %m")));
 385                 }
 386                 else if (rc > 0 && FD_ISSET(syslogPipe[0], &rfds))
 387                 {
 388                         bytesRead = piperead(syslogPipe[0],
 389                                                                  logbuffer + bytes_in_logbuffer,
 390                                                                  sizeof(logbuffer) - bytes_in_logbuffer);
 391                         if (bytesRead < 0)
 392                         {
 393                                 if (errno != EINTR)
 394                                         ereport(LOG,
 395                                                         (errcode_for_socket_access(),
 396                                                          errmsg("could not read from logger pipe: %m")));
 397                         }
 398                         else if (bytesRead > 0)
 399                         {
 400                                 bytes_in_logbuffer += bytesRead;
 401                                 process_pipe_input(logbuffer, &bytes_in_logbuffer);
 402                                 continue;
 403                         }
 404                         else
 405                         {
 406                                 /*
 407                                  * Zero bytes read when select() is saying read-ready means
 408                                  * EOF on the pipe: that is, there are no longer any processes
 409                                  * with the pipe write end open.  Therefore, the postmaster
 410                                  * and all backends are shut down, and we are done.
 411                                  */
 412                                 pipe_eof_seen = true;
 413
 414                                 /* if there's any data left then force it out now */
 415                                 flush_pipe_input(logbuffer, &bytes_in_logbuffer);
 416                         }
 417                 }
 418 #else                                                   /* WIN32 */
 419
 420                 /*
 421                  * On Windows we leave it to a separate thread to transfer data and
 422                  * detect pipe EOF.  The main thread just wakes up once a second to
 423                  * check for SIGHUP and rotation conditions.
 424                  */
 425                 pg_usleep(1000000L);
 426 #endif   /* WIN32 */
 427
 428                 if (pipe_eof_seen)
 429                 {
 430                         /*
 431                          * seeing this message on the real stderr is annoying - so we make
 432                          * it DEBUG1 to suppress in normal use.
 433                          */
 434                         ereport(DEBUG1,
 435                                         (errmsg("logger shutting down")));
 436
 437                         /*
 438                          * Normal exit from the syslogger is here.      Note that we
 439                          * deliberately do not close syslogFile before exiting; this is to
 440                          * allow for the possibility of elog messages being generated
 441                          * inside proc_exit.  Regular exit() will take care of flushing
 442                          * and closing stdio channels.
 443                          */
 444                         proc_exit(0);
 445                 }
 446         }
 447 }
 448
 449 /*
 450  * Postmaster subroutine to start a syslogger subprocess.
 451  */
 452 int
 453 SysLogger_Start(void)
 454 {
 455         pid_t           sysloggerPid;
 456         char       *filename;
 457
 458         if (!Logging_collector)
 459                 return 0;
 460
 461         /*
 462          * If first time through, create the pipe which will receive stderr
 463          * output.
 464          *
 465          * If the syslogger crashes and needs to be restarted, we continue to use
 466          * the same pipe (indeed must do so, since extant backends will be writing
 467          * into that pipe).
 468          *
 469          * This means the postmaster must continue to hold the read end of the
 470          * pipe open, so we can pass it down to the reincarnated syslogger. This
 471          * is a bit klugy but we have little choice.
 472          */
 473 #ifndef WIN32
 474         if (syslogPipe[0] < 0)
 475         {
 476                 if (pgpipe(syslogPipe) < 0)
 477                         ereport(FATAL,
 478                                         (errcode_for_socket_access(),
 479                                          (errmsg("could not create pipe for syslog: %m"))));
 480         }
 481 #else
 482         if (!syslogPipe[0])
 483         {
 484                 SECURITY_ATTRIBUTES sa;
 485
 486                 memset(&sa, 0, sizeof(SECURITY_ATTRIBUTES));
 487                 sa.nLength = sizeof(SECURITY_ATTRIBUTES);
 488                 sa.bInheritHandle = TRUE;
 489
 490                 if (!CreatePipe(&syslogPipe[0], &syslogPipe[1], &sa, 32768))
 491                         ereport(FATAL,
 492                                         (errcode_for_file_access(),
 493                                          (errmsg("could not create pipe for syslog: %m"))));
 494         }
 495 #endif
 496
 497         /*
 498          * Create log directory if not present; ignore errors
 499          */
 500         mkdir(Log_directory, 0700);
 501
 502         /*
 503          * The initial logfile is created right in the postmaster, to verify that
 504          * the Log_directory is writable.
 505          */
 506         filename = logfile_getname(time(NULL), NULL);
 507
 508         syslogFile = fopen(filename, "a");
 509
 510         if (!syslogFile)
 511                 ereport(FATAL,
 512                                 (errcode_for_file_access(),
 513                                  (errmsg("could not create log file \"%s\": %m",
 514                                                  filename))));
 515
 516         setvbuf(syslogFile, NULL, LBF_MODE, 0);
 517
 518         pfree(filename);
 519
 520 #ifdef EXEC_BACKEND
 521         switch ((sysloggerPid = syslogger_forkexec()))
 522 #else
 523         switch ((sysloggerPid = fork_process()))
 524 #endif
 525         {
 526                 case -1:
 527                         ereport(LOG,
 528                                         (errmsg("could not fork system logger: %m")));
 529                         return 0;
 530
 531 #ifndef EXEC_BACKEND
 532                 case 0:
 533                         /* in postmaster child ... */
 534                         /* Close the postmaster's sockets */
 535                         ClosePostmasterPorts(true);
 536
 537                         /* Lose the postmaster's on-exit routines */
 538                         on_exit_reset();
 539
 540                         /* Drop our connection to postmaster's shared memory, as well */
 541                         PGSharedMemoryDetach();
 542
 543                         /* do the work */
 544                         SysLoggerMain(0, NULL);
 545                         break;
 546 #endif
 547
 548                 default:
 549                         /* success, in postmaster */
 550
 551                         /* now we redirect stderr, if not done already */
 552                         if (!redirection_done)
 553                         {
 554 #ifndef WIN32
 555                                 fflush(stdout);
 556                                 if (dup2(syslogPipe[1], fileno(stdout)) < 0)
 557                                         ereport(FATAL,
 558                                                         (errcode_for_file_access(),
 559                                                          errmsg("could not redirect stdout: %m")));
 560                                 fflush(stderr);
 561                                 if (dup2(syslogPipe[1], fileno(stderr)) < 0)
 562                                         ereport(FATAL,
 563                                                         (errcode_for_file_access(),
 564                                                          errmsg("could not redirect stderr: %m")));
 565                                 /* Now we are done with the write end of the pipe. */
 566                                 close(syslogPipe[1]);
 567                                 syslogPipe[1] = -1;
 568 #else
 569                                 int                     fd;
 570
 571                                 /*
 572                                  * open the pipe in binary mode and make sure stderr is binary
 573                                  * after it's been dup'ed into, to avoid disturbing the pipe
 574                                  * chunking protocol.
 575                                  */
 576                                 fflush(stderr);
 577                                 fd = _open_osfhandle((long) syslogPipe[1],
 578                                                                          _O_APPEND | _O_BINARY);
 579                                 if (dup2(fd, _fileno(stderr)) < 0)
 580                                         ereport(FATAL,
 581                                                         (errcode_for_file_access(),
 582                                                          errmsg("could not redirect stderr: %m")));
 583                                 close(fd);
 584                                 _setmode(_fileno(stderr), _O_BINARY);
 585                                 /* Now we are done with the write end of the pipe. */
 586                                 CloseHandle(syslogPipe[1]);
 587                                 syslogPipe[1] = 0;
 588 #endif
 589                                 redirection_done = true;
 590                         }
 591
 592                         /* postmaster will never write the file; close it */
 593                         fclose(syslogFile);
 594                         syslogFile = NULL;
 595                         return (int) sysloggerPid;
 596         }
 597
 598         /* we should never reach here */
 599         return 0;
 600 }
 601
 602
 603 #ifdef EXEC_BACKEND
 604
 605 /*
 606  * syslogger_forkexec() -
 607  *
 608  * Format up the arglist for, then fork and exec, a syslogger process
 609  */
 610 static pid_t
 611 syslogger_forkexec(void)
 612 {
 613         char       *av[10];
 614         int                     ac = 0;
 615         char            filenobuf[32];
 616
 617         av[ac++] = "postgres";
 618         av[ac++] = "--forklog";
 619         av[ac++] = NULL;                        /* filled in by postmaster_forkexec */
 620
 621         /* static variables (those not passed by write_backend_variables) */
 622 #ifndef WIN32
 623         if (syslogFile != NULL)
 624                 snprintf(filenobuf, sizeof(filenobuf), "%d",
 625                                  fileno(syslogFile));
 626         else
 627                 strcpy(filenobuf, "-1");
 628 #else                                                   /* WIN32 */
 629         if (syslogFile != NULL)
 630                 snprintf(filenobuf, sizeof(filenobuf), "%ld",
 631                                  _get_osfhandle(_fileno(syslogFile)));
 632         else
 633                 strcpy(filenobuf, "0");
 634 #endif   /* WIN32 */
 635         av[ac++] = filenobuf;
 636
 637         av[ac] = NULL;
 638         Assert(ac < lengthof(av));
 639
 640         return postmaster_forkexec(ac, av);
 641 }
 642
 643 /*
 644  * syslogger_parseArgs() -
 645  *
 646  * Extract data from the arglist for exec'ed syslogger process
 647  */
 648 static void
 649 syslogger_parseArgs(int argc, char *argv[])
 650 {
 651         int                     fd;
 652
 653         Assert(argc == 4);
 654         argv += 3;
 655
 656 #ifndef WIN32
 657         fd = atoi(*argv++);
 658         if (fd != -1)
 659         {
 660                 syslogFile = fdopen(fd, "a");
 661                 setvbuf(syslogFile, NULL, LBF_MODE, 0);
 662         }
 663 #else                                                   /* WIN32 */
 664         fd = atoi(*argv++);
 665         if (fd != 0)
 666         {
 667                 fd = _open_osfhandle(fd, _O_APPEND | _O_TEXT);
 668                 if (fd > 0)
 669                 {
 670                         syslogFile = fdopen(fd, "a");
 671                         setvbuf(syslogFile, NULL, LBF_MODE, 0);
 672                 }
 673         }
 674 #endif   /* WIN32 */
 675 }
 676 #endif   /* EXEC_BACKEND */
 677
 678
 679 /* --------------------------------
 680  *              pipe protocol handling
 681  * --------------------------------
 682  */
 683
 684 /*
 685  * Process data received through the syslogger pipe.
 686  *
 687  * This routine interprets the log pipe protocol which sends log messages as
 688  * (hopefully atomic) chunks - such chunks are detected and reassembled here.
 689  *
 690  * The protocol has a header that starts with two nul bytes, then has a 16 bit
 691  * length, the pid of the sending process, and a flag to indicate if it is
 692  * the last chunk in a message. Incomplete chunks are saved until we read some
 693  * more, and non-final chunks are accumulated until we get the final chunk.
 694  *
 695  * All of this is to avoid 2 problems:
 696  * . partial messages being written to logfiles (messes rotation), and
 697  * . messages from different backends being interleaved (messages garbled).
 698  *
 699  * Any non-protocol messages are written out directly. These should only come
 700  * from non-PostgreSQL sources, however (e.g. third party libraries writing to
 701  * stderr).
 702  *
 703  * logbuffer is the data input buffer, and *bytes_in_logbuffer is the number
 704  * of bytes present.  On exit, any not-yet-eaten data is left-justified in
 705  * logbuffer, and *bytes_in_logbuffer is updated.
 706  */
 707 static void
 708 process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
 709 {
 710         char       *cursor = logbuffer;
 711         int                     count = *bytes_in_logbuffer;
 712         int                     dest = LOG_DESTINATION_STDERR;
 713
 714         /* While we have enough for a header, process data... */
 715         while (count >= (int) sizeof(PipeProtoHeader))
 716         {
 717                 PipeProtoHeader p;
 718                 int                     chunklen;
 719
 720                 /* Do we have a valid header? */
 721                 memcpy(&p, cursor, sizeof(PipeProtoHeader));
 722                 if (p.nuls[0] == '\0' && p.nuls[1] == '\0' &&
 723                         p.len > 0 && p.len <= PIPE_MAX_PAYLOAD &&
 724                         p.pid != 0 &&
 725                         (p.is_last == 't' || p.is_last == 'f' ||
 726                          p.is_last == 'T' || p.is_last == 'F'))
 727                 {
 728                         chunklen = PIPE_HEADER_SIZE + p.len;
 729
 730                         /* Fall out of loop if we don't have the whole chunk yet */
 731                         if (count < chunklen)
 732                                 break;
 733
 734                         dest = (p.is_last == 'T' || p.is_last == 'F') ?
 735                                 LOG_DESTINATION_CSVLOG : LOG_DESTINATION_STDERR;
 736
 737                         if (p.is_last == 'f' || p.is_last == 'F')
 738                         {
 739                                 /*
 740                                  * Save a complete non-final chunk in the per-pid buffer if
 741                                  * possible - if not just write it out.
 742                                  */
 743                                 int                     free_slot = -1,
 744                                                         existing_slot = -1;
 745                                 int                     i;
 746                                 StringInfo      str;
 747
 748                                 for (i = 0; i < CHUNK_SLOTS; i++)
 749                                 {
 750                                         if (saved_chunks[i].pid == p.pid)
 751                                         {
 752                                                 existing_slot = i;
 753                                                 break;
 754                                         }
 755                                         if (free_slot < 0 && saved_chunks[i].pid == 0)
 756                                                 free_slot = i;
 757                                 }
 758                                 if (existing_slot >= 0)
 759                                 {
 760                                         str = &(saved_chunks[existing_slot].data);
 761                                         appendBinaryStringInfo(str,
 762                                                                                    cursor + PIPE_HEADER_SIZE,
 763                                                                                    p.len);
 764                                 }
 765                                 else if (free_slot >= 0)
 766                                 {
 767                                         saved_chunks[free_slot].pid = p.pid;
 768                                         str = &(saved_chunks[free_slot].data);
 769                                         initStringInfo(str);
 770                                         appendBinaryStringInfo(str,
 771                                                                                    cursor + PIPE_HEADER_SIZE,
 772                                                                                    p.len);
 773                                 }
 774                                 else
 775                                 {
 776                                         /*
 777                                          * If there is no free slot we'll just have to take our
 778                                          * chances and write out a partial message and hope that
 779                                          * it's not followed by something from another pid.
 780                                          */
 781                                         write_syslogger_file(cursor + PIPE_HEADER_SIZE, p.len,
 782                                                                                  dest);
 783                                 }
 784                         }
 785                         else
 786                         {
 787                                 /*
 788                                  * Final chunk --- add it to anything saved for that pid, and
 789                                  * either way write the whole thing out.
 790                                  */
 791                                 int                     existing_slot = -1;
 792                                 int                     i;
 793                                 StringInfo      str;
 794
 795                                 for (i = 0; i < CHUNK_SLOTS; i++)
 796                                 {
 797                                         if (saved_chunks[i].pid == p.pid)
 798                                         {
 799                                                 existing_slot = i;
 800                                                 break;
 801                                         }
 802                                 }
 803                                 if (existing_slot >= 0)
 804                                 {
 805                                         str = &(saved_chunks[existing_slot].data);
 806                                         appendBinaryStringInfo(str,
 807                                                                                    cursor + PIPE_HEADER_SIZE,
 808                                                                                    p.len);
 809                                         write_syslogger_file(str->data, str->len, dest);
 810                                         saved_chunks[existing_slot].pid = 0;
 811                                         pfree(str->data);
 812                                 }
 813                                 else
 814                                 {
 815                                         /* The whole message was one chunk, evidently. */
 816                                         write_syslogger_file(cursor + PIPE_HEADER_SIZE, p.len,
 817                                                                                  dest);
 818                                 }
 819                         }
 820
 821                         /* Finished processing this chunk */
 822                         cursor += chunklen;
 823                         count -= chunklen;
 824                 }
 825                 else
 826                 {
 827                         /* Process non-protocol data */
 828
 829                         /*
 830                          * Look for the start of a protocol header.  If found, dump data
 831                          * up to there and repeat the loop.  Otherwise, dump it all and
 832                          * fall out of the loop.  (Note: we want to dump it all if at all
 833                          * possible, so as to avoid dividing non-protocol messages across
 834                          * logfiles.  We expect that in many scenarios, a non-protocol
 835                          * message will arrive all in one read(), and we want to respect
 836                          * the read() boundary if possible.)
 837                          */
 838                         for (chunklen = 1; chunklen < count; chunklen++)
 839                         {
 840                                 if (cursor[chunklen] == '\0')
 841                                         break;
 842                         }
 843                         /* fall back on the stderr log as the destination */
 844                         write_syslogger_file(cursor, chunklen, LOG_DESTINATION_STDERR);
 845                         cursor += chunklen;
 846                         count -= chunklen;
 847                 }
 848         }
 849
 850         /* We don't have a full chunk, so left-align what remains in the buffer */
 851         if (count > 0 && cursor != logbuffer)
 852                 memmove(logbuffer, cursor, count);
 853         *bytes_in_logbuffer = count;
 854 }
 855
 856 /*
 857  * Force out any buffered data
 858  *
 859  * This is currently used only at syslogger shutdown, but could perhaps be
 860  * useful at other times, so it is careful to leave things in a clean state.
 861  */
 862 static void
 863 flush_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
 864 {
 865         int                     i;
 866         StringInfo      str;
 867
 868         /* Dump any incomplete protocol messages */
 869         for (i = 0; i < CHUNK_SLOTS; i++)
 870         {
 871                 if (saved_chunks[i].pid != 0)
 872                 {
 873                         str = &(saved_chunks[i].data);
 874                         write_syslogger_file(str->data, str->len, LOG_DESTINATION_STDERR);
 875                         saved_chunks[i].pid = 0;
 876                         pfree(str->data);
 877                 }
 878         }
 879
 880         /*
 881          * Force out any remaining pipe data as-is; we don't bother trying to
 882          * remove any protocol headers that may exist in it.
 883          */
 884         if (*bytes_in_logbuffer > 0)
 885                 write_syslogger_file(logbuffer, *bytes_in_logbuffer,
 886                                                          LOG_DESTINATION_STDERR);
 887         *bytes_in_logbuffer = 0;
 888 }
 889
 890
 891 /* --------------------------------
 892  *              logfile routines
 893  * --------------------------------
 894  */
 895
 896 /*
 897  * Write text to the currently open logfile
 898  *
 899  * This is exported so that elog.c can call it when am_syslogger is true.
 900  * This allows the syslogger process to record elog messages of its own,
 901  * even though its stderr does not point at the syslog pipe.
 902  */
 903 void
 904 write_syslogger_file(const char *buffer, int count, int destination)
 905 {
 906         int                     rc;
 907         FILE       *logfile;
 908
 909         if (destination == LOG_DESTINATION_CSVLOG && csvlogFile == NULL)
 910                 open_csvlogfile();
 911
 912         logfile = destination == LOG_DESTINATION_CSVLOG ? csvlogFile : syslogFile;
 913
 914 #ifndef WIN32
 915         rc = fwrite(buffer, 1, count, logfile);
 916 #else
 917         EnterCriticalSection(&sysfileSection);
 918         rc = fwrite(buffer, 1, count, logfile);
 919         LeaveCriticalSection(&sysfileSection);
 920 #endif
 921
 922         /* can't use ereport here because of possible recursion */
 923         if (rc != count)
 924                 write_stderr("could not write to log file: %s\n", strerror(errno));
 925 }
 926
 927 #ifdef WIN32
 928
 929 /*
 930  * Worker thread to transfer data from the pipe to the current logfile.
 931  *
 932  * We need this because on Windows, WaitForSingleObject does not work on
 933  * unnamed pipes: it always reports "signaled", so the blocking ReadFile won't
 934  * allow for SIGHUP; and select is for sockets only.
 935  */
 936 static unsigned int __stdcall
 937 pipeThread(void *arg)
 938 {
 939         char            logbuffer[READ_BUF_SIZE];
 940         int                     bytes_in_logbuffer = 0;
 941
 942         for (;;)
 943         {
 944                 DWORD           bytesRead;
 945
 946                 if (!ReadFile(syslogPipe[0],
 947                                           logbuffer + bytes_in_logbuffer,
 948                                           sizeof(logbuffer) - bytes_in_logbuffer,
 949                                           &bytesRead, 0))
 950                 {
 951                         DWORD           error = GetLastError();
 952
 953                         if (error == ERROR_HANDLE_EOF ||
 954                                 error == ERROR_BROKEN_PIPE)
 955                                 break;
 956                         _dosmaperr(error);
 957                         ereport(LOG,
 958                                         (errcode_for_file_access(),
 959                                          errmsg("could not read from logger pipe: %m")));
 960                 }
 961                 else if (bytesRead > 0)
 962                 {
 963                         bytes_in_logbuffer += bytesRead;
 964                         process_pipe_input(logbuffer, &bytes_in_logbuffer);
 965                 }
 966         }
 967
 968         /* We exit the above loop only upon detecting pipe EOF */
 969         pipe_eof_seen = true;
 970
 971         /* if there's any data left then force it out now */
 972         flush_pipe_input(logbuffer, &bytes_in_logbuffer);
 973
 974         _endthread();
 975         return 0;
 976 }
 977 #endif   /* WIN32 */
 978
 979 /*
 980  * open the csv log file - we do this opportunistically, because
 981  * we don't know if CSV logging will be wanted.
 982  */
 983 static void
 984 open_csvlogfile(void)
 985 {
 986         char       *filename;
 987         FILE       *fh;
 988
 989         filename = logfile_getname(time(NULL), ".csv");
 990
 991         fh = fopen(filename, "a");
 992
 993         if (!fh)
 994                 ereport(FATAL,
 995                                 (errcode_for_file_access(),
 996                                  (errmsg("could not create log file \"%s\": %m",
 997                                                  filename))));
 998
 999         setvbuf(fh, NULL, LBF_MODE, 0);
1000
1001 #ifdef WIN32
1002         _setmode(_fileno(fh), _O_TEXT);         /* use CRLF line endings on Windows */
1003 #endif
1004
1005         csvlogFile = fh;
1006
1007         pfree(filename);
1008
1009 }
1010
1011 /*
1012  * perform logfile rotation
1013  */
1014 static void
1015 logfile_rotate(bool time_based_rotation, int size_rotation_for)
1016 {
1017         char       *filename;
1018         char       *csvfilename = NULL;
1019         FILE       *fh;
1020
1021         rotation_requested = false;
1022
1023         /*
1024          * When doing a time-based rotation, invent the new logfile name based on
1025          * the planned rotation time, not current time, to avoid "slippage" in the
1026          * file name when we don't do the rotation immediately.
1027          */
1028         if (time_based_rotation)
1029         {
1030                 filename = logfile_getname(next_rotation_time, NULL);
1031                 if (csvlogFile != NULL)
1032                         csvfilename = logfile_getname(next_rotation_time, ".csv");
1033         }
1034         else
1035         {
1036                 filename = logfile_getname(time(NULL), NULL);
1037                 if (csvlogFile != NULL)
1038                         csvfilename = logfile_getname(time(NULL), ".csv");
1039         }
1040
1041         /*
1042          * Decide whether to overwrite or append.  We can overwrite if (a)
1043          * Log_truncate_on_rotation is set, (b) the rotation was triggered by
1044          * elapsed time and not something else, and (c) the computed file name is
1045          * different from what we were previously logging into.
1046          *
1047          * Note: during the first rotation after forking off from the postmaster,
1048          * last_file_name will be NULL.  (We don't bother to set it in the
1049          * postmaster because it ain't gonna work in the EXEC_BACKEND case.) So we
1050          * will always append in that situation, even though truncating would
1051          * usually be safe.
1052          *
1053          * For consistency, we treat CSV logs the same even though they aren't
1054          * opened in the postmaster.
1055          */
1056         if (time_based_rotation || (size_rotation_for & LOG_DESTINATION_STDERR))
1057         {
1058                 if (Log_truncate_on_rotation && time_based_rotation &&
1059                         last_file_name != NULL && strcmp(filename, last_file_name) != 0)
1060                         fh = fopen(filename, "w");
1061                 else
1062                         fh = fopen(filename, "a");
1063
1064                 if (!fh)
1065                 {
1066                         int                     saveerrno = errno;
1067
1068                         ereport(LOG,
1069                                         (errcode_for_file_access(),
1070                                          errmsg("could not open new log file \"%s\": %m",
1071                                                         filename)));
1072
1073                         /*
1074                          * ENFILE/EMFILE are not too surprising on a busy system; just
1075                          * keep using the old file till we manage to get a new one.
1076                          * Otherwise, assume something's wrong with Log_directory and stop
1077                          * trying to create files.
1078                          */
1079                         if (saveerrno != ENFILE && saveerrno != EMFILE)
1080                         {
1081                                 ereport(LOG,
1082                                                 (errmsg("disabling automatic rotation (use SIGHUP to reenable)")));
1083                                 Log_RotationAge = 0;
1084                                 Log_RotationSize = 0;
1085                         }
1086                         pfree(filename);
1087                         return;
1088                 }
1089
1090                 setvbuf(fh, NULL, LBF_MODE, 0);
1091
1092 #ifdef WIN32
1093                 _setmode(_fileno(fh), _O_TEXT); /* use CRLF line endings on Windows */
1094 #endif
1095
1096                 /* On Windows, need to interlock against data-transfer thread */
1097 #ifdef WIN32
1098                 EnterCriticalSection(&sysfileSection);
1099 #endif
1100                 fclose(syslogFile);
1101                 syslogFile = fh;
1102 #ifdef WIN32
1103                 LeaveCriticalSection(&sysfileSection);
1104 #endif
1105
1106                 /* instead of pfree'ing filename, remember it for next time */
1107                 if (last_file_name != NULL)
1108                         pfree(last_file_name);
1109                 last_file_name = filename;
1110
1111
1112         }
1113
1114         /* same as above, but for csv file. */
1115
1116         if (csvlogFile != NULL && (
1117                                                            time_based_rotation ||
1118                                                            (size_rotation_for & LOG_DESTINATION_STDERR)))
1119         {
1120                 if (Log_truncate_on_rotation && time_based_rotation &&
1121                         last_csvfile_name != NULL &&
1122                         strcmp(csvfilename, last_csvfile_name) != 0)
1123
1124                         fh = fopen(csvfilename, "w");
1125                 else
1126                         fh = fopen(csvfilename, "a");
1127
1128                 if (!fh)
1129                 {
1130                         int                     saveerrno = errno;
1131
1132                         ereport(LOG,
1133                                         (errcode_for_file_access(),
1134                                          errmsg("could not open new log file \"%s\": %m",
1135                                                         csvfilename)));
1136
1137                         /*
1138                          * ENFILE/EMFILE are not too surprising on a busy system; just
1139                          * keep using the old file till we manage to get a new one.
1140                          * Otherwise, assume something's wrong with Log_directory and stop
1141                          * trying to create files.
1142                          */
1143                         if (saveerrno != ENFILE && saveerrno != EMFILE)
1144                         {
1145                                 ereport(LOG,
1146                                                 (errmsg("disabling automatic rotation (use SIGHUP to reenable)")));
1147                                 Log_RotationAge = 0;
1148                                 Log_RotationSize = 0;
1149                         }
1150                         pfree(csvfilename);
1151                         return;
1152                 }
1153
1154                 setvbuf(fh, NULL, LBF_MODE, 0);
1155
1156 #ifdef WIN32
1157                 _setmode(_fileno(fh), _O_TEXT); /* use CRLF line endings on Windows */
1158 #endif
1159
1160                 /* On Windows, need to interlock against data-transfer thread */
1161 #ifdef WIN32
1162                 EnterCriticalSection(&sysfileSection);
1163 #endif
1164                 fclose(csvlogFile);
1165                 csvlogFile = fh;
1166 #ifdef WIN32
1167                 LeaveCriticalSection(&sysfileSection);
1168 #endif
1169
1170                 /* instead of pfree'ing filename, remember it for next time */
1171                 if (last_csvfile_name != NULL)
1172                         pfree(last_csvfile_name);
1173                 last_csvfile_name = filename;
1174         }
1175
1176         set_next_rotation_time();
1177
1178 }
1179
1180
1181 /*
1182  * construct logfile name using timestamp information
1183  *
1184  * Result is palloc'd.
1185  */
1186 static char *
1187 logfile_getname(pg_time_t timestamp, char *suffix)
1188 {
1189         char       *filename;
1190         int                     len;
1191
1192         filename = palloc(MAXPGPATH);
1193
1194         snprintf(filename, MAXPGPATH, "%s/", Log_directory);
1195
1196         len = strlen(filename);
1197
1198         if (strchr(Log_filename, '%'))
1199         {
1200                 /* treat it as a strftime pattern */
1201                 pg_strftime(filename + len, MAXPGPATH - len, Log_filename,
1202                                         pg_localtime(&timestamp, log_timezone));
1203         }
1204         else
1205         {
1206                 /* no strftime escapes, so append timestamp to new filename */
1207                 snprintf(filename + len, MAXPGPATH - len, "%s.%lu",
1208                                  Log_filename, (unsigned long) timestamp);
1209         }
1210
1211         if (suffix != NULL)
1212         {
1213                 len = strlen(filename);
1214                 if (len > 4 && (strcmp(filename + (len - 4), ".log") == 0))
1215                         len -= 4;
1216                 strncpy(filename + len, suffix, MAXPGPATH - len);
1217         }
1218
1219         return filename;
1220 }
1221
1222 /*
1223  * Determine the next planned rotation time, and store in next_rotation_time.
1224  */
1225 static void
1226 set_next_rotation_time(void)
1227 {
1228         pg_time_t       now;
1229         struct pg_tm *tm;
1230         int                     rotinterval;
1231
1232         /* nothing to do if time-based rotation is disabled */
1233         if (Log_RotationAge <= 0)
1234                 return;
1235
1236         /*
1237          * The requirements here are to choose the next time > now that is a
1238          * "multiple" of the log rotation interval.  "Multiple" can be interpreted
1239          * fairly loosely.      In this version we align to log_timezone rather than
1240          * GMT.
1241          */
1242         rotinterval = Log_RotationAge * SECS_PER_MINUTE;        /* convert to seconds */
1243         now = (pg_time_t) time(NULL);
1244         tm = pg_localtime(&now, log_timezone);
1245         now += tm->tm_gmtoff;
1246         now -= now % rotinterval;
1247         now += rotinterval;
1248         now -= tm->tm_gmtoff;
1249         next_rotation_time = now;
1250 }
1251
1252 /* --------------------------------
1253  *              signal handler routines
1254  * --------------------------------
1255  */
1256
1257 /* SIGHUP: set flag to reload config file */
1258 static void
1259 sigHupHandler(SIGNAL_ARGS)
1260 {
1261         got_SIGHUP = true;
1262 }
1263
1264 /* SIGUSR1: set flag to rotate logfile */
1265 static void
1266 sigUsr1Handler(SIGNAL_ARGS)
1267 {
1268         rotation_requested = true;
1269 }