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