LCOV - code coverage report
Current view: top level - src/backend/postmaster - syslogger.c (source / functions) Hit Total Coverage
Test: PostgreSQL 16beta1 Lines: 235 382 61.5 %
Date: 2023-05-31 03:12:18 Functions: 14 14 100.0 %
Legend: Lines: hit not hit

          Line data    Source code
       1             : /*-------------------------------------------------------------------------
       2             :  *
       3             :  * syslogger.c
       4             :  *
       5             :  * The system logger (syslogger) appeared 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 a user-selectable naming scheme.
      13             :  *
      14             :  * Author: Andreas Pflug <pgadmin@pse-consulting.de>
      15             :  *
      16             :  * Copyright (c) 2004-2023, PostgreSQL Global Development Group
      17             :  *
      18             :  *
      19             :  * IDENTIFICATION
      20             :  *    src/backend/postmaster/syslogger.c
      21             :  *
      22             :  *-------------------------------------------------------------------------
      23             :  */
      24             : #include "postgres.h"
      25             : 
      26             : #include <fcntl.h>
      27             : #include <limits.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 "common/file_perm.h"
      35             : #include "lib/stringinfo.h"
      36             : #include "libpq/pqsignal.h"
      37             : #include "miscadmin.h"
      38             : #include "nodes/pg_list.h"
      39             : #include "pgstat.h"
      40             : #include "pgtime.h"
      41             : #include "port/pg_bitutils.h"
      42             : #include "postmaster/fork_process.h"
      43             : #include "postmaster/interrupt.h"
      44             : #include "postmaster/postmaster.h"
      45             : #include "postmaster/syslogger.h"
      46             : #include "storage/dsm.h"
      47             : #include "storage/fd.h"
      48             : #include "storage/ipc.h"
      49             : #include "storage/latch.h"
      50             : #include "storage/pg_shmem.h"
      51             : #include "tcop/tcopprot.h"
      52             : #include "utils/guc.h"
      53             : #include "utils/ps_status.h"
      54             : #include "utils/timestamp.h"
      55             : 
      56             : /*
      57             :  * We read() into a temp buffer twice as big as a chunk, so that any fragment
      58             :  * left after processing can be moved down to the front and we'll still have
      59             :  * room to read a full chunk.
      60             :  */
      61             : #define READ_BUF_SIZE (2 * PIPE_CHUNK_SIZE)
      62             : 
      63             : /* Log rotation signal file path, relative to $PGDATA */
      64             : #define LOGROTATE_SIGNAL_FILE   "logrotate"
      65             : 
      66             : 
      67             : /*
      68             :  * GUC parameters.  Logging_collector cannot be changed after postmaster
      69             :  * start, but the rest can change at SIGHUP.
      70             :  */
      71             : bool        Logging_collector = false;
      72             : int         Log_RotationAge = HOURS_PER_DAY * MINS_PER_HOUR;
      73             : int         Log_RotationSize = 10 * 1024;
      74             : char       *Log_directory = NULL;
      75             : char       *Log_filename = NULL;
      76             : bool        Log_truncate_on_rotation = false;
      77             : int         Log_file_mode = S_IRUSR | S_IWUSR;
      78             : 
      79             : extern bool redirection_done;
      80             : 
      81             : /*
      82             :  * Private state
      83             :  */
      84             : static pg_time_t next_rotation_time;
      85             : static bool pipe_eof_seen = false;
      86             : static bool rotation_disabled = false;
      87             : static FILE *syslogFile = NULL;
      88             : static FILE *csvlogFile = NULL;
      89             : static FILE *jsonlogFile = NULL;
      90             : NON_EXEC_STATIC pg_time_t first_syslogger_file_time = 0;
      91             : static char *last_sys_file_name = NULL;
      92             : static char *last_csv_file_name = NULL;
      93             : static char *last_json_file_name = NULL;
      94             : 
      95             : /*
      96             :  * Buffers for saving partial messages from different backends.
      97             :  *
      98             :  * Keep NBUFFER_LISTS lists of these, with the entry for a given source pid
      99             :  * being in the list numbered (pid % NBUFFER_LISTS), so as to cut down on
     100             :  * the number of entries we have to examine for any one incoming message.
     101             :  * There must never be more than one entry for the same source pid.
     102             :  *
     103             :  * An inactive buffer is not removed from its list, just held for re-use.
     104             :  * An inactive buffer has pid == 0 and undefined contents of data.
     105             :  */
     106             : typedef struct
     107             : {
     108             :     int32       pid;            /* PID of source process */
     109             :     StringInfoData data;        /* accumulated data, as a StringInfo */
     110             : } save_buffer;
     111             : 
     112             : #define NBUFFER_LISTS 256
     113             : static List *buffer_lists[NBUFFER_LISTS];
     114             : 
     115             : /* These must be exported for EXEC_BACKEND case ... annoying */
     116             : #ifndef WIN32
     117             : int         syslogPipe[2] = {-1, -1};
     118             : #else
     119             : HANDLE      syslogPipe[2] = {0, 0};
     120             : #endif
     121             : 
     122             : #ifdef WIN32
     123             : static HANDLE threadHandle = 0;
     124             : static CRITICAL_SECTION sysloggerSection;
     125             : #endif
     126             : 
     127             : /*
     128             :  * Flags set by interrupt handlers for later service in the main loop.
     129             :  */
     130             : static volatile sig_atomic_t rotation_requested = false;
     131             : 
     132             : 
     133             : /* Local subroutines */
     134             : #ifdef EXEC_BACKEND
     135             : static int  syslogger_fdget(FILE *file);
     136             : static FILE *syslogger_fdopen(int fd);
     137             : static pid_t syslogger_forkexec(void);
     138             : static void syslogger_parseArgs(int argc, char *argv[]);
     139             : #endif
     140             : NON_EXEC_STATIC void SysLoggerMain(int argc, char *argv[]) pg_attribute_noreturn();
     141             : static void process_pipe_input(char *logbuffer, int *bytes_in_logbuffer);
     142             : static void flush_pipe_input(char *logbuffer, int *bytes_in_logbuffer);
     143             : static FILE *logfile_open(const char *filename, const char *mode,
     144             :                           bool allow_errors);
     145             : 
     146             : #ifdef WIN32
     147             : static unsigned int __stdcall pipeThread(void *arg);
     148             : #endif
     149             : static void logfile_rotate(bool time_based_rotation, int size_rotation_for);
     150             : static bool logfile_rotate_dest(bool time_based_rotation,
     151             :                                 int size_rotation_for, pg_time_t fntime,
     152             :                                 int target_dest, char **last_file_name,
     153             :                                 FILE **logFile);
     154             : static char *logfile_getname(pg_time_t timestamp, const char *suffix);
     155             : static void set_next_rotation_time(void);
     156             : static void sigUsr1Handler(SIGNAL_ARGS);
     157             : static void update_metainfo_datafile(void);
     158             : 
     159             : 
     160             : /*
     161             :  * Main entry point for syslogger process
     162             :  * argc/argv parameters are valid only in EXEC_BACKEND case.
     163             :  */
     164             : NON_EXEC_STATIC void
     165           2 : SysLoggerMain(int argc, char *argv[])
     166             : {
     167             : #ifndef WIN32
     168             :     char        logbuffer[READ_BUF_SIZE];
     169           2 :     int         bytes_in_logbuffer = 0;
     170             : #endif
     171             :     char       *currentLogDir;
     172             :     char       *currentLogFilename;
     173             :     int         currentLogRotationAge;
     174             :     pg_time_t   now;
     175             :     WaitEventSet *wes;
     176             : 
     177           2 :     now = MyStartTime;
     178             : 
     179             : #ifdef EXEC_BACKEND
     180             :     syslogger_parseArgs(argc, argv);
     181             : #endif                          /* EXEC_BACKEND */
     182             : 
     183           2 :     MyBackendType = B_LOGGER;
     184           2 :     init_ps_display(NULL);
     185             : 
     186             :     /*
     187             :      * If we restarted, our stderr is already redirected into our own input
     188             :      * pipe.  This is of course pretty useless, not to mention that it
     189             :      * interferes with detecting pipe EOF.  Point stderr to /dev/null. This
     190             :      * assumes that all interesting messages generated in the syslogger will
     191             :      * come through elog.c and will be sent to write_syslogger_file.
     192             :      */
     193           2 :     if (redirection_done)
     194             :     {
     195           0 :         int         fd = open(DEVNULL, O_WRONLY, 0);
     196             : 
     197             :         /*
     198             :          * The closes might look redundant, but they are not: we want to be
     199             :          * darn sure the pipe gets closed even if the open failed.  We can
     200             :          * survive running with stderr pointing nowhere, but we can't afford
     201             :          * to have extra pipe input descriptors hanging around.
     202             :          *
     203             :          * As we're just trying to reset these to go to DEVNULL, there's not
     204             :          * much point in checking for failure from the close/dup2 calls here,
     205             :          * if they fail then presumably the file descriptors are closed and
     206             :          * any writes will go into the bitbucket anyway.
     207             :          */
     208           0 :         close(STDOUT_FILENO);
     209           0 :         close(STDERR_FILENO);
     210           0 :         if (fd != -1)
     211             :         {
     212           0 :             (void) dup2(fd, STDOUT_FILENO);
     213           0 :             (void) dup2(fd, STDERR_FILENO);
     214           0 :             close(fd);
     215             :         }
     216             :     }
     217             : 
     218             :     /*
     219             :      * Syslogger's own stderr can't be the syslogPipe, so set it back to text
     220             :      * mode if we didn't just close it. (It was set to binary in
     221             :      * SubPostmasterMain).
     222             :      */
     223             : #ifdef WIN32
     224             :     else
     225             :         _setmode(STDERR_FILENO, _O_TEXT);
     226             : #endif
     227             : 
     228             :     /*
     229             :      * Also close our copy of the write end of the pipe.  This is needed to
     230             :      * ensure we can detect pipe EOF correctly.  (But note that in the restart
     231             :      * case, the postmaster already did this.)
     232             :      */
     233             : #ifndef WIN32
     234           2 :     if (syslogPipe[1] >= 0)
     235           2 :         close(syslogPipe[1]);
     236           2 :     syslogPipe[1] = -1;
     237             : #else
     238             :     if (syslogPipe[1])
     239             :         CloseHandle(syslogPipe[1]);
     240             :     syslogPipe[1] = 0;
     241             : #endif
     242             : 
     243             :     /*
     244             :      * Properly accept or ignore signals the postmaster might send us
     245             :      *
     246             :      * Note: we ignore all termination signals, and instead exit only when all
     247             :      * upstream processes are gone, to ensure we don't miss any dying gasps of
     248             :      * broken backends...
     249             :      */
     250             : 
     251           2 :     pqsignal(SIGHUP, SignalHandlerForConfigReload); /* set flag to read config
     252             :                                                      * file */
     253           2 :     pqsignal(SIGINT, SIG_IGN);
     254           2 :     pqsignal(SIGTERM, SIG_IGN);
     255           2 :     pqsignal(SIGQUIT, SIG_IGN);
     256           2 :     pqsignal(SIGALRM, SIG_IGN);
     257           2 :     pqsignal(SIGPIPE, SIG_IGN);
     258           2 :     pqsignal(SIGUSR1, sigUsr1Handler);  /* request log rotation */
     259           2 :     pqsignal(SIGUSR2, SIG_IGN);
     260             : 
     261             :     /*
     262             :      * Reset some signals that are accepted by postmaster but not here
     263             :      */
     264           2 :     pqsignal(SIGCHLD, SIG_DFL);
     265             : 
     266           2 :     sigprocmask(SIG_SETMASK, &UnBlockSig, NULL);
     267             : 
     268             : #ifdef WIN32
     269             :     /* Fire up separate data transfer thread */
     270             :     InitializeCriticalSection(&sysloggerSection);
     271             :     EnterCriticalSection(&sysloggerSection);
     272             : 
     273             :     threadHandle = (HANDLE) _beginthreadex(NULL, 0, pipeThread, NULL, 0, NULL);
     274             :     if (threadHandle == 0)
     275             :         elog(FATAL, "could not create syslogger data transfer thread: %m");
     276             : #endif                          /* WIN32 */
     277             : 
     278             :     /*
     279             :      * Remember active logfiles' name(s).  We recompute 'em from the reference
     280             :      * time because passing down just the pg_time_t is a lot cheaper than
     281             :      * passing a whole file path in the EXEC_BACKEND case.
     282             :      */
     283           2 :     last_sys_file_name = logfile_getname(first_syslogger_file_time, NULL);
     284           2 :     if (csvlogFile != NULL)
     285           2 :         last_csv_file_name = logfile_getname(first_syslogger_file_time, ".csv");
     286           2 :     if (jsonlogFile != NULL)
     287           2 :         last_json_file_name = logfile_getname(first_syslogger_file_time, ".json");
     288             : 
     289             :     /* remember active logfile parameters */
     290           2 :     currentLogDir = pstrdup(Log_directory);
     291           2 :     currentLogFilename = pstrdup(Log_filename);
     292           2 :     currentLogRotationAge = Log_RotationAge;
     293             :     /* set next planned rotation time */
     294           2 :     set_next_rotation_time();
     295           2 :     update_metainfo_datafile();
     296             : 
     297             :     /*
     298             :      * Reset whereToSendOutput, as the postmaster will do (but hasn't yet, at
     299             :      * the point where we forked).  This prevents duplicate output of messages
     300             :      * from syslogger itself.
     301             :      */
     302           2 :     whereToSendOutput = DestNone;
     303             : 
     304             :     /*
     305             :      * Set up a reusable WaitEventSet object we'll use to wait for our latch,
     306             :      * and (except on Windows) our socket.
     307             :      *
     308             :      * Unlike all other postmaster child processes, we'll ignore postmaster
     309             :      * death because we want to collect final log output from all backends and
     310             :      * then exit last.  We'll do that by running until we see EOF on the
     311             :      * syslog pipe, which implies that all other backends have exited
     312             :      * (including the postmaster).
     313             :      */
     314           2 :     wes = CreateWaitEventSet(CurrentMemoryContext, 2);
     315           2 :     AddWaitEventToSet(wes, WL_LATCH_SET, PGINVALID_SOCKET, MyLatch, NULL);
     316             : #ifndef WIN32
     317           2 :     AddWaitEventToSet(wes, WL_SOCKET_READABLE, syslogPipe[0], NULL, NULL);
     318             : #endif
     319             : 
     320             :     /* main worker loop */
     321             :     for (;;)
     322          82 :     {
     323          84 :         bool        time_based_rotation = false;
     324          84 :         int         size_rotation_for = 0;
     325             :         long        cur_timeout;
     326             :         WaitEvent   event;
     327             : 
     328             : #ifndef WIN32
     329             :         int         rc;
     330             : #endif
     331             : 
     332             :         /* Clear any already-pending wakeups */
     333          84 :         ResetLatch(MyLatch);
     334             : 
     335             :         /*
     336             :          * Process any requests or signals received recently.
     337             :          */
     338          84 :         if (ConfigReloadPending)
     339             :         {
     340           0 :             ConfigReloadPending = false;
     341           0 :             ProcessConfigFile(PGC_SIGHUP);
     342             : 
     343             :             /*
     344             :              * Check if the log directory or filename pattern changed in
     345             :              * postgresql.conf. If so, force rotation to make sure we're
     346             :              * writing the logfiles in the right place.
     347             :              */
     348           0 :             if (strcmp(Log_directory, currentLogDir) != 0)
     349             :             {
     350           0 :                 pfree(currentLogDir);
     351           0 :                 currentLogDir = pstrdup(Log_directory);
     352           0 :                 rotation_requested = true;
     353             : 
     354             :                 /*
     355             :                  * Also, create new directory if not present; ignore errors
     356             :                  */
     357           0 :                 (void) MakePGDirectory(Log_directory);
     358             :             }
     359           0 :             if (strcmp(Log_filename, currentLogFilename) != 0)
     360             :             {
     361           0 :                 pfree(currentLogFilename);
     362           0 :                 currentLogFilename = pstrdup(Log_filename);
     363           0 :                 rotation_requested = true;
     364             :             }
     365             : 
     366             :             /*
     367             :              * Force a rotation if CSVLOG output was just turned on or off and
     368             :              * we need to open or close csvlogFile accordingly.
     369             :              */
     370           0 :             if (((Log_destination & LOG_DESTINATION_CSVLOG) != 0) !=
     371             :                 (csvlogFile != NULL))
     372           0 :                 rotation_requested = true;
     373             : 
     374             :             /*
     375             :              * Force a rotation if JSONLOG output was just turned on or off
     376             :              * and we need to open or close jsonlogFile accordingly.
     377             :              */
     378           0 :             if (((Log_destination & LOG_DESTINATION_JSONLOG) != 0) !=
     379             :                 (jsonlogFile != NULL))
     380           0 :                 rotation_requested = true;
     381             : 
     382             :             /*
     383             :              * If rotation time parameter changed, reset next rotation time,
     384             :              * but don't immediately force a rotation.
     385             :              */
     386           0 :             if (currentLogRotationAge != Log_RotationAge)
     387             :             {
     388           0 :                 currentLogRotationAge = Log_RotationAge;
     389           0 :                 set_next_rotation_time();
     390             :             }
     391             : 
     392             :             /*
     393             :              * If we had a rotation-disabling failure, re-enable rotation
     394             :              * attempts after SIGHUP, and force one immediately.
     395             :              */
     396           0 :             if (rotation_disabled)
     397             :             {
     398           0 :                 rotation_disabled = false;
     399           0 :                 rotation_requested = true;
     400             :             }
     401             : 
     402             :             /*
     403             :              * Force rewriting last log filename when reloading configuration.
     404             :              * Even if rotation_requested is false, log_destination may have
     405             :              * been changed and we don't want to wait the next file rotation.
     406             :              */
     407           0 :             update_metainfo_datafile();
     408             :         }
     409             : 
     410          84 :         if (Log_RotationAge > 0 && !rotation_disabled)
     411             :         {
     412             :             /* Do a logfile rotation if it's time */
     413           0 :             now = (pg_time_t) time(NULL);
     414           0 :             if (now >= next_rotation_time)
     415           0 :                 rotation_requested = time_based_rotation = true;
     416             :         }
     417             : 
     418          84 :         if (!rotation_requested && Log_RotationSize > 0 && !rotation_disabled)
     419             :         {
     420             :             /* Do a rotation if file is too big */
     421          82 :             if (ftell(syslogFile) >= Log_RotationSize * 1024L)
     422             :             {
     423           0 :                 rotation_requested = true;
     424           0 :                 size_rotation_for |= LOG_DESTINATION_STDERR;
     425             :             }
     426          82 :             if (csvlogFile != NULL &&
     427          82 :                 ftell(csvlogFile) >= Log_RotationSize * 1024L)
     428             :             {
     429           0 :                 rotation_requested = true;
     430           0 :                 size_rotation_for |= LOG_DESTINATION_CSVLOG;
     431             :             }
     432          82 :             if (jsonlogFile != NULL &&
     433          82 :                 ftell(jsonlogFile) >= Log_RotationSize * 1024L)
     434             :             {
     435           0 :                 rotation_requested = true;
     436           0 :                 size_rotation_for |= LOG_DESTINATION_JSONLOG;
     437             :             }
     438             :         }
     439             : 
     440          84 :         if (rotation_requested)
     441             :         {
     442             :             /*
     443             :              * Force rotation when both values are zero. It means the request
     444             :              * was sent by pg_rotate_logfile() or "pg_ctl logrotate".
     445             :              */
     446           2 :             if (!time_based_rotation && size_rotation_for == 0)
     447           2 :                 size_rotation_for = LOG_DESTINATION_STDERR |
     448             :                     LOG_DESTINATION_CSVLOG |
     449             :                     LOG_DESTINATION_JSONLOG;
     450           2 :             logfile_rotate(time_based_rotation, size_rotation_for);
     451             :         }
     452             : 
     453             :         /*
     454             :          * Calculate time till next time-based rotation, so that we don't
     455             :          * sleep longer than that.  We assume the value of "now" obtained
     456             :          * above is still close enough.  Note we can't make this calculation
     457             :          * until after calling logfile_rotate(), since it will advance
     458             :          * next_rotation_time.
     459             :          *
     460             :          * Also note that we need to beware of overflow in calculation of the
     461             :          * timeout: with large settings of Log_RotationAge, next_rotation_time
     462             :          * could be more than INT_MAX msec in the future.  In that case we'll
     463             :          * wait no more than INT_MAX msec, and try again.
     464             :          */
     465          84 :         if (Log_RotationAge > 0 && !rotation_disabled)
     466           0 :         {
     467             :             pg_time_t   delay;
     468             : 
     469           0 :             delay = next_rotation_time - now;
     470           0 :             if (delay > 0)
     471             :             {
     472           0 :                 if (delay > INT_MAX / 1000)
     473           0 :                     delay = INT_MAX / 1000;
     474           0 :                 cur_timeout = delay * 1000L;    /* msec */
     475             :             }
     476             :             else
     477           0 :                 cur_timeout = 0;
     478             :         }
     479             :         else
     480          84 :             cur_timeout = -1L;
     481             : 
     482             :         /*
     483             :          * Sleep until there's something to do
     484             :          */
     485             : #ifndef WIN32
     486          84 :         rc = WaitEventSetWait(wes, cur_timeout, &event, 1,
     487             :                               WAIT_EVENT_SYSLOGGER_MAIN);
     488             : 
     489          84 :         if (rc == 1 && event.events == WL_SOCKET_READABLE)
     490             :         {
     491             :             int         bytesRead;
     492             : 
     493          82 :             bytesRead = read(syslogPipe[0],
     494             :                              logbuffer + bytes_in_logbuffer,
     495             :                              sizeof(logbuffer) - bytes_in_logbuffer);
     496          82 :             if (bytesRead < 0)
     497             :             {
     498           0 :                 if (errno != EINTR)
     499           0 :                     ereport(LOG,
     500             :                             (errcode_for_socket_access(),
     501             :                              errmsg("could not read from logger pipe: %m")));
     502             :             }
     503          82 :             else if (bytesRead > 0)
     504             :             {
     505          80 :                 bytes_in_logbuffer += bytesRead;
     506          80 :                 process_pipe_input(logbuffer, &bytes_in_logbuffer);
     507          80 :                 continue;
     508             :             }
     509             :             else
     510             :             {
     511             :                 /*
     512             :                  * Zero bytes read when select() is saying read-ready means
     513             :                  * EOF on the pipe: that is, there are no longer any processes
     514             :                  * with the pipe write end open.  Therefore, the postmaster
     515             :                  * and all backends are shut down, and we are done.
     516             :                  */
     517           2 :                 pipe_eof_seen = true;
     518             : 
     519             :                 /* if there's any data left then force it out now */
     520           2 :                 flush_pipe_input(logbuffer, &bytes_in_logbuffer);
     521             :             }
     522             :         }
     523             : #else                           /* WIN32 */
     524             : 
     525             :         /*
     526             :          * On Windows we leave it to a separate thread to transfer data and
     527             :          * detect pipe EOF.  The main thread just wakes up to handle SIGHUP
     528             :          * and rotation conditions.
     529             :          *
     530             :          * Server code isn't generally thread-safe, so we ensure that only one
     531             :          * of the threads is active at a time by entering the critical section
     532             :          * whenever we're not sleeping.
     533             :          */
     534             :         LeaveCriticalSection(&sysloggerSection);
     535             : 
     536             :         (void) WaitEventSetWait(wes, cur_timeout, &event, 1,
     537             :                                 WAIT_EVENT_SYSLOGGER_MAIN);
     538             : 
     539             :         EnterCriticalSection(&sysloggerSection);
     540             : #endif                          /* WIN32 */
     541             : 
     542           4 :         if (pipe_eof_seen)
     543             :         {
     544             :             /*
     545             :              * seeing this message on the real stderr is annoying - so we make
     546             :              * it DEBUG1 to suppress in normal use.
     547             :              */
     548           2 :             ereport(DEBUG1,
     549             :                     (errmsg_internal("logger shutting down")));
     550             : 
     551             :             /*
     552             :              * Normal exit from the syslogger is here.  Note that we
     553             :              * deliberately do not close syslogFile before exiting; this is to
     554             :              * allow for the possibility of elog messages being generated
     555             :              * inside proc_exit.  Regular exit() will take care of flushing
     556             :              * and closing stdio channels.
     557             :              */
     558           2 :             proc_exit(0);
     559             :         }
     560             :     }
     561             : }
     562             : 
     563             : /*
     564             :  * Postmaster subroutine to start a syslogger subprocess.
     565             :  */
     566             : int
     567        1186 : SysLogger_Start(void)
     568             : {
     569             :     pid_t       sysloggerPid;
     570             :     char       *filename;
     571             : 
     572        1186 :     if (!Logging_collector)
     573        1184 :         return 0;
     574             : 
     575             :     /*
     576             :      * If first time through, create the pipe which will receive stderr
     577             :      * output.
     578             :      *
     579             :      * If the syslogger crashes and needs to be restarted, we continue to use
     580             :      * the same pipe (indeed must do so, since extant backends will be writing
     581             :      * into that pipe).
     582             :      *
     583             :      * This means the postmaster must continue to hold the read end of the
     584             :      * pipe open, so we can pass it down to the reincarnated syslogger. This
     585             :      * is a bit klugy but we have little choice.
     586             :      *
     587             :      * Also note that we don't bother counting the pipe FDs by calling
     588             :      * Reserve/ReleaseExternalFD.  There's no real need to account for them
     589             :      * accurately in the postmaster or syslogger process, and both ends of the
     590             :      * pipe will wind up closed in all other postmaster children.
     591             :      */
     592             : #ifndef WIN32
     593           2 :     if (syslogPipe[0] < 0)
     594             :     {
     595           2 :         if (pipe(syslogPipe) < 0)
     596           0 :             ereport(FATAL,
     597             :                     (errcode_for_socket_access(),
     598             :                      errmsg("could not create pipe for syslog: %m")));
     599             :     }
     600             : #else
     601             :     if (!syslogPipe[0])
     602             :     {
     603             :         SECURITY_ATTRIBUTES sa;
     604             : 
     605             :         memset(&sa, 0, sizeof(SECURITY_ATTRIBUTES));
     606             :         sa.nLength = sizeof(SECURITY_ATTRIBUTES);
     607             :         sa.bInheritHandle = TRUE;
     608             : 
     609             :         if (!CreatePipe(&syslogPipe[0], &syslogPipe[1], &sa, 32768))
     610             :             ereport(FATAL,
     611             :                     (errcode_for_file_access(),
     612             :                      errmsg("could not create pipe for syslog: %m")));
     613             :     }
     614             : #endif
     615             : 
     616             :     /*
     617             :      * Create log directory if not present; ignore errors
     618             :      */
     619           2 :     (void) MakePGDirectory(Log_directory);
     620             : 
     621             :     /*
     622             :      * The initial logfile is created right in the postmaster, to verify that
     623             :      * the Log_directory is writable.  We save the reference time so that the
     624             :      * syslogger child process can recompute this file name.
     625             :      *
     626             :      * It might look a bit strange to re-do this during a syslogger restart,
     627             :      * but we must do so since the postmaster closed syslogFile after the
     628             :      * previous fork (and remembering that old file wouldn't be right anyway).
     629             :      * Note we always append here, we won't overwrite any existing file.  This
     630             :      * is consistent with the normal rules, because by definition this is not
     631             :      * a time-based rotation.
     632             :      */
     633           2 :     first_syslogger_file_time = time(NULL);
     634             : 
     635           2 :     filename = logfile_getname(first_syslogger_file_time, NULL);
     636             : 
     637           2 :     syslogFile = logfile_open(filename, "a", false);
     638             : 
     639           2 :     pfree(filename);
     640             : 
     641             :     /*
     642             :      * Likewise for the initial CSV log file, if that's enabled.  (Note that
     643             :      * we open syslogFile even when only CSV output is nominally enabled,
     644             :      * since some code paths will write to syslogFile anyway.)
     645             :      */
     646           2 :     if (Log_destination & LOG_DESTINATION_CSVLOG)
     647             :     {
     648           2 :         filename = logfile_getname(first_syslogger_file_time, ".csv");
     649             : 
     650           2 :         csvlogFile = logfile_open(filename, "a", false);
     651             : 
     652           2 :         pfree(filename);
     653             :     }
     654             : 
     655             :     /*
     656             :      * Likewise for the initial JSON log file, if that's enabled.  (Note that
     657             :      * we open syslogFile even when only JSON output is nominally enabled,
     658             :      * since some code paths will write to syslogFile anyway.)
     659             :      */
     660           2 :     if (Log_destination & LOG_DESTINATION_JSONLOG)
     661             :     {
     662           2 :         filename = logfile_getname(first_syslogger_file_time, ".json");
     663             : 
     664           2 :         jsonlogFile = logfile_open(filename, "a", false);
     665             : 
     666           2 :         pfree(filename);
     667             :     }
     668             : 
     669             : #ifdef EXEC_BACKEND
     670             :     switch ((sysloggerPid = syslogger_forkexec()))
     671             : #else
     672           2 :     switch ((sysloggerPid = fork_process()))
     673             : #endif
     674             :     {
     675           0 :         case -1:
     676           0 :             ereport(LOG,
     677             :                     (errmsg("could not fork system logger: %m")));
     678           0 :             return 0;
     679             : 
     680             : #ifndef EXEC_BACKEND
     681           2 :         case 0:
     682             :             /* in postmaster child ... */
     683           2 :             InitPostmasterChild();
     684             : 
     685             :             /* Close the postmaster's sockets */
     686           2 :             ClosePostmasterPorts(true);
     687             : 
     688             :             /* Drop our connection to postmaster's shared memory, as well */
     689           2 :             dsm_detach_all();
     690           2 :             PGSharedMemoryDetach();
     691             : 
     692             :             /* do the work */
     693           2 :             SysLoggerMain(0, NULL);
     694             :             break;
     695             : #endif
     696             : 
     697           2 :         default:
     698             :             /* success, in postmaster */
     699             : 
     700             :             /* now we redirect stderr, if not done already */
     701           2 :             if (!redirection_done)
     702             :             {
     703             : #ifdef WIN32
     704             :                 int         fd;
     705             : #endif
     706             : 
     707             :                 /*
     708             :                  * Leave a breadcrumb trail when redirecting, in case the user
     709             :                  * forgets that redirection is active and looks only at the
     710             :                  * original stderr target file.
     711             :                  */
     712           2 :                 ereport(LOG,
     713             :                         (errmsg("redirecting log output to logging collector process"),
     714             :                          errhint("Future log output will appear in directory \"%s\".",
     715             :                                  Log_directory)));
     716             : 
     717             : #ifndef WIN32
     718           2 :                 fflush(stdout);
     719           2 :                 if (dup2(syslogPipe[1], STDOUT_FILENO) < 0)
     720           0 :                     ereport(FATAL,
     721             :                             (errcode_for_file_access(),
     722             :                              errmsg("could not redirect stdout: %m")));
     723           2 :                 fflush(stderr);
     724           2 :                 if (dup2(syslogPipe[1], STDERR_FILENO) < 0)
     725           0 :                     ereport(FATAL,
     726             :                             (errcode_for_file_access(),
     727             :                              errmsg("could not redirect stderr: %m")));
     728             :                 /* Now we are done with the write end of the pipe. */
     729           2 :                 close(syslogPipe[1]);
     730           2 :                 syslogPipe[1] = -1;
     731             : #else
     732             : 
     733             :                 /*
     734             :                  * open the pipe in binary mode and make sure stderr is binary
     735             :                  * after it's been dup'ed into, to avoid disturbing the pipe
     736             :                  * chunking protocol.
     737             :                  */
     738             :                 fflush(stderr);
     739             :                 fd = _open_osfhandle((intptr_t) syslogPipe[1],
     740             :                                      _O_APPEND | _O_BINARY);
     741             :                 if (dup2(fd, STDERR_FILENO) < 0)
     742             :                     ereport(FATAL,
     743             :                             (errcode_for_file_access(),
     744             :                              errmsg("could not redirect stderr: %m")));
     745             :                 close(fd);
     746             :                 _setmode(STDERR_FILENO, _O_BINARY);
     747             : 
     748             :                 /*
     749             :                  * Now we are done with the write end of the pipe.
     750             :                  * CloseHandle() must not be called because the preceding
     751             :                  * close() closes the underlying handle.
     752             :                  */
     753             :                 syslogPipe[1] = 0;
     754             : #endif
     755           2 :                 redirection_done = true;
     756             :             }
     757             : 
     758             :             /* postmaster will never write the file(s); close 'em */
     759           2 :             fclose(syslogFile);
     760           2 :             syslogFile = NULL;
     761           2 :             if (csvlogFile != NULL)
     762             :             {
     763           2 :                 fclose(csvlogFile);
     764           2 :                 csvlogFile = NULL;
     765             :             }
     766           2 :             if (jsonlogFile != NULL)
     767             :             {
     768           2 :                 fclose(jsonlogFile);
     769           2 :                 jsonlogFile = NULL;
     770             :             }
     771           2 :             return (int) sysloggerPid;
     772             :     }
     773             : 
     774             :     /* we should never reach here */
     775             :     return 0;
     776             : }
     777             : 
     778             : 
     779             : #ifdef EXEC_BACKEND
     780             : 
     781             : /*
     782             :  * syslogger_fdget() -
     783             :  *
     784             :  * Utility wrapper to grab the file descriptor of an opened error output
     785             :  * file.  Used when building the command to fork the logging collector.
     786             :  */
     787             : static int
     788             : syslogger_fdget(FILE *file)
     789             : {
     790             : #ifndef WIN32
     791             :     if (file != NULL)
     792             :         return fileno(file);
     793             :     else
     794             :         return -1;
     795             : #else
     796             :     if (file != NULL)
     797             :         return (int) _get_osfhandle(_fileno(file));
     798             :     else
     799             :         return 0;
     800             : #endif                          /* WIN32 */
     801             : }
     802             : 
     803             : /*
     804             :  * syslogger_fdopen() -
     805             :  *
     806             :  * Utility wrapper to re-open an error output file, using the given file
     807             :  * descriptor.  Used when parsing arguments in a forked logging collector.
     808             :  */
     809             : static FILE *
     810             : syslogger_fdopen(int fd)
     811             : {
     812             :     FILE       *file = NULL;
     813             : 
     814             : #ifndef WIN32
     815             :     if (fd != -1)
     816             :     {
     817             :         file = fdopen(fd, "a");
     818             :         setvbuf(file, NULL, PG_IOLBF, 0);
     819             :     }
     820             : #else                           /* WIN32 */
     821             :     if (fd != 0)
     822             :     {
     823             :         fd = _open_osfhandle(fd, _O_APPEND | _O_TEXT);
     824             :         if (fd > 0)
     825             :         {
     826             :             file = fdopen(fd, "a");
     827             :             setvbuf(file, NULL, PG_IOLBF, 0);
     828             :         }
     829             :     }
     830             : #endif                          /* WIN32 */
     831             : 
     832             :     return file;
     833             : }
     834             : 
     835             : /*
     836             :  * syslogger_forkexec() -
     837             :  *
     838             :  * Format up the arglist for, then fork and exec, a syslogger process
     839             :  */
     840             : static pid_t
     841             : syslogger_forkexec(void)
     842             : {
     843             :     char       *av[10];
     844             :     int         ac = 0;
     845             :     char        filenobuf[32];
     846             :     char        csvfilenobuf[32];
     847             :     char        jsonfilenobuf[32];
     848             : 
     849             :     av[ac++] = "postgres";
     850             :     av[ac++] = "--forklog";
     851             :     av[ac++] = NULL;            /* filled in by postmaster_forkexec */
     852             : 
     853             :     /* static variables (those not passed by write_backend_variables) */
     854             :     snprintf(filenobuf, sizeof(filenobuf), "%d",
     855             :              syslogger_fdget(syslogFile));
     856             :     av[ac++] = filenobuf;
     857             :     snprintf(csvfilenobuf, sizeof(csvfilenobuf), "%d",
     858             :              syslogger_fdget(csvlogFile));
     859             :     av[ac++] = csvfilenobuf;
     860             :     snprintf(jsonfilenobuf, sizeof(jsonfilenobuf), "%d",
     861             :              syslogger_fdget(jsonlogFile));
     862             :     av[ac++] = jsonfilenobuf;
     863             : 
     864             :     av[ac] = NULL;
     865             :     Assert(ac < lengthof(av));
     866             : 
     867             :     return postmaster_forkexec(ac, av);
     868             : }
     869             : 
     870             : /*
     871             :  * syslogger_parseArgs() -
     872             :  *
     873             :  * Extract data from the arglist for exec'ed syslogger process
     874             :  */
     875             : static void
     876             : syslogger_parseArgs(int argc, char *argv[])
     877             : {
     878             :     int         fd;
     879             : 
     880             :     Assert(argc == 6);
     881             :     argv += 3;
     882             : 
     883             :     /*
     884             :      * Re-open the error output files that were opened by SysLogger_Start().
     885             :      *
     886             :      * We expect this will always succeed, which is too optimistic, but if it
     887             :      * fails there's not a lot we can do to report the problem anyway.  As
     888             :      * coded, we'll just crash on a null pointer dereference after failure...
     889             :      */
     890             :     fd = atoi(*argv++);
     891             :     syslogFile = syslogger_fdopen(fd);
     892             :     fd = atoi(*argv++);
     893             :     csvlogFile = syslogger_fdopen(fd);
     894             :     fd = atoi(*argv++);
     895             :     jsonlogFile = syslogger_fdopen(fd);
     896             : }
     897             : #endif                          /* EXEC_BACKEND */
     898             : 
     899             : 
     900             : /* --------------------------------
     901             :  *      pipe protocol handling
     902             :  * --------------------------------
     903             :  */
     904             : 
     905             : /*
     906             :  * Process data received through the syslogger pipe.
     907             :  *
     908             :  * This routine interprets the log pipe protocol which sends log messages as
     909             :  * (hopefully atomic) chunks - such chunks are detected and reassembled here.
     910             :  *
     911             :  * The protocol has a header that starts with two nul bytes, then has a 16 bit
     912             :  * length, the pid of the sending process, and a flag to indicate if it is
     913             :  * the last chunk in a message. Incomplete chunks are saved until we read some
     914             :  * more, and non-final chunks are accumulated until we get the final chunk.
     915             :  *
     916             :  * All of this is to avoid 2 problems:
     917             :  * . partial messages being written to logfiles (messes rotation), and
     918             :  * . messages from different backends being interleaved (messages garbled).
     919             :  *
     920             :  * Any non-protocol messages are written out directly. These should only come
     921             :  * from non-PostgreSQL sources, however (e.g. third party libraries writing to
     922             :  * stderr).
     923             :  *
     924             :  * logbuffer is the data input buffer, and *bytes_in_logbuffer is the number
     925             :  * of bytes present.  On exit, any not-yet-eaten data is left-justified in
     926             :  * logbuffer, and *bytes_in_logbuffer is updated.
     927             :  */
     928             : static void
     929          80 : process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
     930             : {
     931          80 :     char       *cursor = logbuffer;
     932          80 :     int         count = *bytes_in_logbuffer;
     933          80 :     int         dest = LOG_DESTINATION_STDERR;
     934             : 
     935             :     /* While we have enough for a header, process data... */
     936         200 :     while (count >= (int) (offsetof(PipeProtoHeader, data) + 1))
     937             :     {
     938             :         PipeProtoHeader p;
     939             :         int         chunklen;
     940             :         bits8       dest_flags;
     941             : 
     942             :         /* Do we have a valid header? */
     943         120 :         memcpy(&p, cursor, offsetof(PipeProtoHeader, data));
     944         120 :         dest_flags = p.flags & (PIPE_PROTO_DEST_STDERR |
     945             :                                 PIPE_PROTO_DEST_CSVLOG |
     946             :                                 PIPE_PROTO_DEST_JSONLOG);
     947         120 :         if (p.nuls[0] == '\0' && p.nuls[1] == '\0' &&
     948         120 :             p.len > 0 && p.len <= PIPE_MAX_PAYLOAD &&
     949         240 :             p.pid != 0 &&
     950         120 :             pg_popcount((char *) &dest_flags, 1) == 1)
     951         120 :         {
     952             :             List       *buffer_list;
     953             :             ListCell   *cell;
     954         120 :             save_buffer *existing_slot = NULL,
     955         120 :                        *free_slot = NULL;
     956             :             StringInfo  str;
     957             : 
     958         120 :             chunklen = PIPE_HEADER_SIZE + p.len;
     959             : 
     960             :             /* Fall out of loop if we don't have the whole chunk yet */
     961         120 :             if (count < chunklen)
     962           0 :                 break;
     963             : 
     964         120 :             if ((p.flags & PIPE_PROTO_DEST_STDERR) != 0)
     965          40 :                 dest = LOG_DESTINATION_STDERR;
     966          80 :             else if ((p.flags & PIPE_PROTO_DEST_CSVLOG) != 0)
     967          40 :                 dest = LOG_DESTINATION_CSVLOG;
     968          40 :             else if ((p.flags & PIPE_PROTO_DEST_JSONLOG) != 0)
     969          40 :                 dest = LOG_DESTINATION_JSONLOG;
     970             :             else
     971             :             {
     972             :                 /* this should never happen as of the header validation */
     973             :                 Assert(false);
     974             :             }
     975             : 
     976             :             /* Locate any existing buffer for this source pid */
     977         120 :             buffer_list = buffer_lists[p.pid % NBUFFER_LISTS];
     978         120 :             foreach(cell, buffer_list)
     979             :             {
     980           0 :                 save_buffer *buf = (save_buffer *) lfirst(cell);
     981             : 
     982           0 :                 if (buf->pid == p.pid)
     983             :                 {
     984           0 :                     existing_slot = buf;
     985           0 :                     break;
     986             :                 }
     987           0 :                 if (buf->pid == 0 && free_slot == NULL)
     988           0 :                     free_slot = buf;
     989             :             }
     990             : 
     991         120 :             if ((p.flags & PIPE_PROTO_IS_LAST) == 0)
     992             :             {
     993             :                 /*
     994             :                  * Save a complete non-final chunk in a per-pid buffer
     995             :                  */
     996           0 :                 if (existing_slot != NULL)
     997             :                 {
     998             :                     /* Add chunk to data from preceding chunks */
     999           0 :                     str = &(existing_slot->data);
    1000           0 :                     appendBinaryStringInfo(str,
    1001           0 :                                            cursor + PIPE_HEADER_SIZE,
    1002           0 :                                            p.len);
    1003             :                 }
    1004             :                 else
    1005             :                 {
    1006             :                     /* First chunk of message, save in a new buffer */
    1007           0 :                     if (free_slot == NULL)
    1008             :                     {
    1009             :                         /*
    1010             :                          * Need a free slot, but there isn't one in the list,
    1011             :                          * so create a new one and extend the list with it.
    1012             :                          */
    1013           0 :                         free_slot = palloc(sizeof(save_buffer));
    1014           0 :                         buffer_list = lappend(buffer_list, free_slot);
    1015           0 :                         buffer_lists[p.pid % NBUFFER_LISTS] = buffer_list;
    1016             :                     }
    1017           0 :                     free_slot->pid = p.pid;
    1018           0 :                     str = &(free_slot->data);
    1019           0 :                     initStringInfo(str);
    1020           0 :                     appendBinaryStringInfo(str,
    1021           0 :                                            cursor + PIPE_HEADER_SIZE,
    1022           0 :                                            p.len);
    1023             :                 }
    1024             :             }
    1025             :             else
    1026             :             {
    1027             :                 /*
    1028             :                  * Final chunk --- add it to anything saved for that pid, and
    1029             :                  * either way write the whole thing out.
    1030             :                  */
    1031         120 :                 if (existing_slot != NULL)
    1032             :                 {
    1033           0 :                     str = &(existing_slot->data);
    1034           0 :                     appendBinaryStringInfo(str,
    1035           0 :                                            cursor + PIPE_HEADER_SIZE,
    1036           0 :                                            p.len);
    1037           0 :                     write_syslogger_file(str->data, str->len, dest);
    1038             :                     /* Mark the buffer unused, and reclaim string storage */
    1039           0 :                     existing_slot->pid = 0;
    1040           0 :                     pfree(str->data);
    1041             :                 }
    1042             :                 else
    1043             :                 {
    1044             :                     /* The whole message was one chunk, evidently. */
    1045         120 :                     write_syslogger_file(cursor + PIPE_HEADER_SIZE, p.len,
    1046             :                                          dest);
    1047             :                 }
    1048             :             }
    1049             : 
    1050             :             /* Finished processing this chunk */
    1051         120 :             cursor += chunklen;
    1052         120 :             count -= chunklen;
    1053             :         }
    1054             :         else
    1055             :         {
    1056             :             /* Process non-protocol data */
    1057             : 
    1058             :             /*
    1059             :              * Look for the start of a protocol header.  If found, dump data
    1060             :              * up to there and repeat the loop.  Otherwise, dump it all and
    1061             :              * fall out of the loop.  (Note: we want to dump it all if at all
    1062             :              * possible, so as to avoid dividing non-protocol messages across
    1063             :              * logfiles.  We expect that in many scenarios, a non-protocol
    1064             :              * message will arrive all in one read(), and we want to respect
    1065             :              * the read() boundary if possible.)
    1066             :              */
    1067           0 :             for (chunklen = 1; chunklen < count; chunklen++)
    1068             :             {
    1069           0 :                 if (cursor[chunklen] == '\0')
    1070           0 :                     break;
    1071             :             }
    1072             :             /* fall back on the stderr log as the destination */
    1073           0 :             write_syslogger_file(cursor, chunklen, LOG_DESTINATION_STDERR);
    1074           0 :             cursor += chunklen;
    1075           0 :             count -= chunklen;
    1076             :         }
    1077             :     }
    1078             : 
    1079             :     /* We don't have a full chunk, so left-align what remains in the buffer */
    1080          80 :     if (count > 0 && cursor != logbuffer)
    1081           0 :         memmove(logbuffer, cursor, count);
    1082          80 :     *bytes_in_logbuffer = count;
    1083          80 : }
    1084             : 
    1085             : /*
    1086             :  * Force out any buffered data
    1087             :  *
    1088             :  * This is currently used only at syslogger shutdown, but could perhaps be
    1089             :  * useful at other times, so it is careful to leave things in a clean state.
    1090             :  */
    1091             : static void
    1092           2 : flush_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
    1093             : {
    1094             :     int         i;
    1095             : 
    1096             :     /* Dump any incomplete protocol messages */
    1097         514 :     for (i = 0; i < NBUFFER_LISTS; i++)
    1098             :     {
    1099         512 :         List       *list = buffer_lists[i];
    1100             :         ListCell   *cell;
    1101             : 
    1102         512 :         foreach(cell, list)
    1103             :         {
    1104           0 :             save_buffer *buf = (save_buffer *) lfirst(cell);
    1105             : 
    1106           0 :             if (buf->pid != 0)
    1107             :             {
    1108           0 :                 StringInfo  str = &(buf->data);
    1109             : 
    1110           0 :                 write_syslogger_file(str->data, str->len,
    1111             :                                      LOG_DESTINATION_STDERR);
    1112             :                 /* Mark the buffer unused, and reclaim string storage */
    1113           0 :                 buf->pid = 0;
    1114           0 :                 pfree(str->data);
    1115             :             }
    1116             :         }
    1117             :     }
    1118             : 
    1119             :     /*
    1120             :      * Force out any remaining pipe data as-is; we don't bother trying to
    1121             :      * remove any protocol headers that may exist in it.
    1122             :      */
    1123           2 :     if (*bytes_in_logbuffer > 0)
    1124           0 :         write_syslogger_file(logbuffer, *bytes_in_logbuffer,
    1125             :                              LOG_DESTINATION_STDERR);
    1126           2 :     *bytes_in_logbuffer = 0;
    1127           2 : }
    1128             : 
    1129             : 
    1130             : /* --------------------------------
    1131             :  *      logfile routines
    1132             :  * --------------------------------
    1133             :  */
    1134             : 
    1135             : /*
    1136             :  * Write text to the currently open logfile
    1137             :  *
    1138             :  * This is exported so that elog.c can call it when MyBackendType is B_LOGGER.
    1139             :  * This allows the syslogger process to record elog messages of its own,
    1140             :  * even though its stderr does not point at the syslog pipe.
    1141             :  */
    1142             : void
    1143         120 : write_syslogger_file(const char *buffer, int count, int destination)
    1144             : {
    1145             :     int         rc;
    1146             :     FILE       *logfile;
    1147             : 
    1148             :     /*
    1149             :      * If we're told to write to a structured log file, but it's not open,
    1150             :      * dump the data to syslogFile (which is always open) instead.  This can
    1151             :      * happen if structured output is enabled after postmaster start and we've
    1152             :      * been unable to open logFile.  There are also race conditions during a
    1153             :      * parameter change whereby backends might send us structured output
    1154             :      * before we open the logFile or after we close it.  Writing formatted
    1155             :      * output to the regular log file isn't great, but it beats dropping log
    1156             :      * output on the floor.
    1157             :      *
    1158             :      * Think not to improve this by trying to open logFile on-the-fly.  Any
    1159             :      * failure in that would lead to recursion.
    1160             :      */
    1161         120 :     if ((destination & LOG_DESTINATION_CSVLOG) && csvlogFile != NULL)
    1162          40 :         logfile = csvlogFile;
    1163          80 :     else if ((destination & LOG_DESTINATION_JSONLOG) && jsonlogFile != NULL)
    1164          40 :         logfile = jsonlogFile;
    1165             :     else
    1166          40 :         logfile = syslogFile;
    1167             : 
    1168         120 :     rc = fwrite(buffer, 1, count, logfile);
    1169             : 
    1170             :     /*
    1171             :      * Try to report any failure.  We mustn't use ereport because it would
    1172             :      * just recurse right back here, but write_stderr is OK: it will write
    1173             :      * either to the postmaster's original stderr, or to /dev/null, but never
    1174             :      * to our input pipe which would result in a different sort of looping.
    1175             :      */
    1176         120 :     if (rc != count)
    1177           0 :         write_stderr("could not write to log file: %s\n", strerror(errno));
    1178         120 : }
    1179             : 
    1180             : #ifdef WIN32
    1181             : 
    1182             : /*
    1183             :  * Worker thread to transfer data from the pipe to the current logfile.
    1184             :  *
    1185             :  * We need this because on Windows, WaitForMultipleObjects does not work on
    1186             :  * unnamed pipes: it always reports "signaled", so the blocking ReadFile won't
    1187             :  * allow for SIGHUP; and select is for sockets only.
    1188             :  */
    1189             : static unsigned int __stdcall
    1190             : pipeThread(void *arg)
    1191             : {
    1192             :     char        logbuffer[READ_BUF_SIZE];
    1193             :     int         bytes_in_logbuffer = 0;
    1194             : 
    1195             :     for (;;)
    1196             :     {
    1197             :         DWORD       bytesRead;
    1198             :         BOOL        result;
    1199             : 
    1200             :         result = ReadFile(syslogPipe[0],
    1201             :                           logbuffer + bytes_in_logbuffer,
    1202             :                           sizeof(logbuffer) - bytes_in_logbuffer,
    1203             :                           &bytesRead, 0);
    1204             : 
    1205             :         /*
    1206             :          * Enter critical section before doing anything that might touch
    1207             :          * global state shared by the main thread. Anything that uses
    1208             :          * palloc()/pfree() in particular are not safe outside the critical
    1209             :          * section.
    1210             :          */
    1211             :         EnterCriticalSection(&sysloggerSection);
    1212             :         if (!result)
    1213             :         {
    1214             :             DWORD       error = GetLastError();
    1215             : 
    1216             :             if (error == ERROR_HANDLE_EOF ||
    1217             :                 error == ERROR_BROKEN_PIPE)
    1218             :                 break;
    1219             :             _dosmaperr(error);
    1220             :             ereport(LOG,
    1221             :                     (errcode_for_file_access(),
    1222             :                      errmsg("could not read from logger pipe: %m")));
    1223             :         }
    1224             :         else if (bytesRead > 0)
    1225             :         {
    1226             :             bytes_in_logbuffer += bytesRead;
    1227             :             process_pipe_input(logbuffer, &bytes_in_logbuffer);
    1228             :         }
    1229             : 
    1230             :         /*
    1231             :          * If we've filled the current logfile, nudge the main thread to do a
    1232             :          * log rotation.
    1233             :          */
    1234             :         if (Log_RotationSize > 0)
    1235             :         {
    1236             :             if (ftell(syslogFile) >= Log_RotationSize * 1024L ||
    1237             :                 (csvlogFile != NULL && ftell(csvlogFile) >= Log_RotationSize * 1024L) ||
    1238             :                 (jsonlogFile != NULL && ftell(jsonlogFile) >= Log_RotationSize * 1024L))
    1239             :                 SetLatch(MyLatch);
    1240             :         }
    1241             :         LeaveCriticalSection(&sysloggerSection);
    1242             :     }
    1243             : 
    1244             :     /* We exit the above loop only upon detecting pipe EOF */
    1245             :     pipe_eof_seen = true;
    1246             : 
    1247             :     /* if there's any data left then force it out now */
    1248             :     flush_pipe_input(logbuffer, &bytes_in_logbuffer);
    1249             : 
    1250             :     /* set the latch to waken the main thread, which will quit */
    1251             :     SetLatch(MyLatch);
    1252             : 
    1253             :     LeaveCriticalSection(&sysloggerSection);
    1254             :     _endthread();
    1255             :     return 0;
    1256             : }
    1257             : #endif                          /* WIN32 */
    1258             : 
    1259             : /*
    1260             :  * Open a new logfile with proper permissions and buffering options.
    1261             :  *
    1262             :  * If allow_errors is true, we just log any open failure and return NULL
    1263             :  * (with errno still correct for the fopen failure).
    1264             :  * Otherwise, errors are treated as fatal.
    1265             :  */
    1266             : static FILE *
    1267          12 : logfile_open(const char *filename, const char *mode, bool allow_errors)
    1268             : {
    1269             :     FILE       *fh;
    1270             :     mode_t      oumask;
    1271             : 
    1272             :     /*
    1273             :      * Note we do not let Log_file_mode disable IWUSR, since we certainly want
    1274             :      * to be able to write the files ourselves.
    1275             :      */
    1276          12 :     oumask = umask((mode_t) ((~(Log_file_mode | S_IWUSR)) & (S_IRWXU | S_IRWXG | S_IRWXO)));
    1277          12 :     fh = fopen(filename, mode);
    1278          12 :     umask(oumask);
    1279             : 
    1280          12 :     if (fh)
    1281             :     {
    1282          12 :         setvbuf(fh, NULL, PG_IOLBF, 0);
    1283             : 
    1284             : #ifdef WIN32
    1285             :         /* use CRLF line endings on Windows */
    1286             :         _setmode(_fileno(fh), _O_TEXT);
    1287             : #endif
    1288             :     }
    1289             :     else
    1290             :     {
    1291           0 :         int         save_errno = errno;
    1292             : 
    1293           0 :         ereport(allow_errors ? LOG : FATAL,
    1294             :                 (errcode_for_file_access(),
    1295             :                  errmsg("could not open log file \"%s\": %m",
    1296             :                         filename)));
    1297           0 :         errno = save_errno;
    1298             :     }
    1299             : 
    1300          12 :     return fh;
    1301             : }
    1302             : 
    1303             : /*
    1304             :  * Do logfile rotation for a single destination, as specified by target_dest.
    1305             :  * The information stored in *last_file_name and *logFile is updated on a
    1306             :  * successful file rotation.
    1307             :  *
    1308             :  * Returns false if the rotation has been stopped, or true to move on to
    1309             :  * the processing of other formats.
    1310             :  */
    1311             : static bool
    1312           6 : logfile_rotate_dest(bool time_based_rotation, int size_rotation_for,
    1313             :                     pg_time_t fntime, int target_dest,
    1314             :                     char **last_file_name, FILE **logFile)
    1315             : {
    1316           6 :     char       *logFileExt = NULL;
    1317             :     char       *filename;
    1318             :     FILE       *fh;
    1319             : 
    1320             :     /*
    1321             :      * If the target destination was just turned off, close the previous file
    1322             :      * and unregister its data.  This cannot happen for stderr as syslogFile
    1323             :      * is assumed to be always opened even if stderr is disabled in
    1324             :      * log_destination.
    1325             :      */
    1326           6 :     if ((Log_destination & target_dest) == 0 &&
    1327             :         target_dest != LOG_DESTINATION_STDERR)
    1328             :     {
    1329           0 :         if (*logFile != NULL)
    1330           0 :             fclose(*logFile);
    1331           0 :         *logFile = NULL;
    1332           0 :         if (*last_file_name != NULL)
    1333           0 :             pfree(*last_file_name);
    1334           0 :         *last_file_name = NULL;
    1335           0 :         return true;
    1336             :     }
    1337             : 
    1338             :     /*
    1339             :      * Leave if it is not time for a rotation or if the target destination has
    1340             :      * no need to do a rotation based on the size of its file.
    1341             :      */
    1342           6 :     if (!time_based_rotation && (size_rotation_for & target_dest) == 0)
    1343           0 :         return true;
    1344             : 
    1345             :     /* file extension depends on the destination type */
    1346           6 :     if (target_dest == LOG_DESTINATION_STDERR)
    1347           2 :         logFileExt = NULL;
    1348           4 :     else if (target_dest == LOG_DESTINATION_CSVLOG)
    1349           2 :         logFileExt = ".csv";
    1350           2 :     else if (target_dest == LOG_DESTINATION_JSONLOG)
    1351           2 :         logFileExt = ".json";
    1352             :     else
    1353             :     {
    1354             :         /* cannot happen */
    1355             :         Assert(false);
    1356             :     }
    1357             : 
    1358             :     /* build the new file name */
    1359           6 :     filename = logfile_getname(fntime, logFileExt);
    1360             : 
    1361             :     /*
    1362             :      * Decide whether to overwrite or append.  We can overwrite if (a)
    1363             :      * Log_truncate_on_rotation is set, (b) the rotation was triggered by
    1364             :      * elapsed time and not something else, and (c) the computed file name is
    1365             :      * different from what we were previously logging into.
    1366             :      */
    1367           6 :     if (Log_truncate_on_rotation && time_based_rotation &&
    1368           0 :         *last_file_name != NULL &&
    1369           0 :         strcmp(filename, *last_file_name) != 0)
    1370           0 :         fh = logfile_open(filename, "w", true);
    1371             :     else
    1372           6 :         fh = logfile_open(filename, "a", true);
    1373             : 
    1374           6 :     if (!fh)
    1375             :     {
    1376             :         /*
    1377             :          * ENFILE/EMFILE are not too surprising on a busy system; just keep
    1378             :          * using the old file till we manage to get a new one.  Otherwise,
    1379             :          * assume something's wrong with Log_directory and stop trying to
    1380             :          * create files.
    1381             :          */
    1382           0 :         if (errno != ENFILE && errno != EMFILE)
    1383             :         {
    1384           0 :             ereport(LOG,
    1385             :                     (errmsg("disabling automatic rotation (use SIGHUP to re-enable)")));
    1386           0 :             rotation_disabled = true;
    1387             :         }
    1388             : 
    1389           0 :         if (filename)
    1390           0 :             pfree(filename);
    1391           0 :         return false;
    1392             :     }
    1393             : 
    1394             :     /* fill in the new information */
    1395           6 :     if (*logFile != NULL)
    1396           6 :         fclose(*logFile);
    1397           6 :     *logFile = fh;
    1398             : 
    1399             :     /* instead of pfree'ing filename, remember it for next time */
    1400           6 :     if (*last_file_name != NULL)
    1401           6 :         pfree(*last_file_name);
    1402           6 :     *last_file_name = filename;
    1403             : 
    1404           6 :     return true;
    1405             : }
    1406             : 
    1407             : /*
    1408             :  * perform logfile rotation
    1409             :  */
    1410             : static void
    1411           2 : logfile_rotate(bool time_based_rotation, int size_rotation_for)
    1412             : {
    1413             :     pg_time_t   fntime;
    1414             : 
    1415           2 :     rotation_requested = false;
    1416             : 
    1417             :     /*
    1418             :      * When doing a time-based rotation, invent the new logfile name based on
    1419             :      * the planned rotation time, not current time, to avoid "slippage" in the
    1420             :      * file name when we don't do the rotation immediately.
    1421             :      */
    1422           2 :     if (time_based_rotation)
    1423           0 :         fntime = next_rotation_time;
    1424             :     else
    1425           2 :         fntime = time(NULL);
    1426             : 
    1427             :     /* file rotation for stderr */
    1428           2 :     if (!logfile_rotate_dest(time_based_rotation, size_rotation_for, fntime,
    1429             :                              LOG_DESTINATION_STDERR, &last_sys_file_name,
    1430             :                              &syslogFile))
    1431           0 :         return;
    1432             : 
    1433             :     /* file rotation for csvlog */
    1434           2 :     if (!logfile_rotate_dest(time_based_rotation, size_rotation_for, fntime,
    1435             :                              LOG_DESTINATION_CSVLOG, &last_csv_file_name,
    1436             :                              &csvlogFile))
    1437           0 :         return;
    1438             : 
    1439             :     /* file rotation for jsonlog */
    1440           2 :     if (!logfile_rotate_dest(time_based_rotation, size_rotation_for, fntime,
    1441             :                              LOG_DESTINATION_JSONLOG, &last_json_file_name,
    1442             :                              &jsonlogFile))
    1443           0 :         return;
    1444             : 
    1445           2 :     update_metainfo_datafile();
    1446             : 
    1447           2 :     set_next_rotation_time();
    1448             : }
    1449             : 
    1450             : 
    1451             : /*
    1452             :  * construct logfile name using timestamp information
    1453             :  *
    1454             :  * If suffix isn't NULL, append it to the name, replacing any ".log"
    1455             :  * that may be in the pattern.
    1456             :  *
    1457             :  * Result is palloc'd.
    1458             :  */
    1459             : static char *
    1460          18 : logfile_getname(pg_time_t timestamp, const char *suffix)
    1461             : {
    1462             :     char       *filename;
    1463             :     int         len;
    1464             : 
    1465          18 :     filename = palloc(MAXPGPATH);
    1466             : 
    1467          18 :     snprintf(filename, MAXPGPATH, "%s/", Log_directory);
    1468             : 
    1469          18 :     len = strlen(filename);
    1470             : 
    1471             :     /* treat Log_filename as a strftime pattern */
    1472          18 :     pg_strftime(filename + len, MAXPGPATH - len, Log_filename,
    1473          18 :                 pg_localtime(&timestamp, log_timezone));
    1474             : 
    1475          18 :     if (suffix != NULL)
    1476             :     {
    1477          12 :         len = strlen(filename);
    1478          12 :         if (len > 4 && (strcmp(filename + (len - 4), ".log") == 0))
    1479          12 :             len -= 4;
    1480          12 :         strlcpy(filename + len, suffix, MAXPGPATH - len);
    1481             :     }
    1482             : 
    1483          18 :     return filename;
    1484             : }
    1485             : 
    1486             : /*
    1487             :  * Determine the next planned rotation time, and store in next_rotation_time.
    1488             :  */
    1489             : static void
    1490           4 : set_next_rotation_time(void)
    1491             : {
    1492             :     pg_time_t   now;
    1493             :     struct pg_tm *tm;
    1494             :     int         rotinterval;
    1495             : 
    1496             :     /* nothing to do if time-based rotation is disabled */
    1497           4 :     if (Log_RotationAge <= 0)
    1498           4 :         return;
    1499             : 
    1500             :     /*
    1501             :      * The requirements here are to choose the next time > now that is a
    1502             :      * "multiple" of the log rotation interval.  "Multiple" can be interpreted
    1503             :      * fairly loosely.  In this version we align to log_timezone rather than
    1504             :      * GMT.
    1505             :      */
    1506           0 :     rotinterval = Log_RotationAge * SECS_PER_MINUTE;    /* convert to seconds */
    1507           0 :     now = (pg_time_t) time(NULL);
    1508           0 :     tm = pg_localtime(&now, log_timezone);
    1509           0 :     now += tm->tm_gmtoff;
    1510           0 :     now -= now % rotinterval;
    1511           0 :     now += rotinterval;
    1512           0 :     now -= tm->tm_gmtoff;
    1513           0 :     next_rotation_time = now;
    1514             : }
    1515             : 
    1516             : /*
    1517             :  * Store the name of the file(s) where the log collector, when enabled, writes
    1518             :  * log messages.  Useful for finding the name(s) of the current log file(s)
    1519             :  * when there is time-based logfile rotation.  Filenames are stored in a
    1520             :  * temporary file and which is renamed into the final destination for
    1521             :  * atomicity.  The file is opened with the same permissions as what gets
    1522             :  * created in the data directory and has proper buffering options.
    1523             :  */
    1524             : static void
    1525           4 : update_metainfo_datafile(void)
    1526             : {
    1527             :     FILE       *fh;
    1528             :     mode_t      oumask;
    1529             : 
    1530           4 :     if (!(Log_destination & LOG_DESTINATION_STDERR) &&
    1531           0 :         !(Log_destination & LOG_DESTINATION_CSVLOG) &&
    1532           0 :         !(Log_destination & LOG_DESTINATION_JSONLOG))
    1533             :     {
    1534           0 :         if (unlink(LOG_METAINFO_DATAFILE) < 0 && errno != ENOENT)
    1535           0 :             ereport(LOG,
    1536             :                     (errcode_for_file_access(),
    1537             :                      errmsg("could not remove file \"%s\": %m",
    1538             :                             LOG_METAINFO_DATAFILE)));
    1539           0 :         return;
    1540             :     }
    1541             : 
    1542             :     /* use the same permissions as the data directory for the new file */
    1543           4 :     oumask = umask(pg_mode_mask);
    1544           4 :     fh = fopen(LOG_METAINFO_DATAFILE_TMP, "w");
    1545           4 :     umask(oumask);
    1546             : 
    1547           4 :     if (fh)
    1548             :     {
    1549           4 :         setvbuf(fh, NULL, PG_IOLBF, 0);
    1550             : 
    1551             : #ifdef WIN32
    1552             :         /* use CRLF line endings on Windows */
    1553             :         _setmode(_fileno(fh), _O_TEXT);
    1554             : #endif
    1555             :     }
    1556             :     else
    1557             :     {
    1558           0 :         ereport(LOG,
    1559             :                 (errcode_for_file_access(),
    1560             :                  errmsg("could not open file \"%s\": %m",
    1561             :                         LOG_METAINFO_DATAFILE_TMP)));
    1562           0 :         return;
    1563             :     }
    1564             : 
    1565           4 :     if (last_sys_file_name && (Log_destination & LOG_DESTINATION_STDERR))
    1566             :     {
    1567           4 :         if (fprintf(fh, "stderr %s\n", last_sys_file_name) < 0)
    1568             :         {
    1569           0 :             ereport(LOG,
    1570             :                     (errcode_for_file_access(),
    1571             :                      errmsg("could not write file \"%s\": %m",
    1572             :                             LOG_METAINFO_DATAFILE_TMP)));
    1573           0 :             fclose(fh);
    1574           0 :             return;
    1575             :         }
    1576             :     }
    1577             : 
    1578           4 :     if (last_csv_file_name && (Log_destination & LOG_DESTINATION_CSVLOG))
    1579             :     {
    1580           4 :         if (fprintf(fh, "csvlog %s\n", last_csv_file_name) < 0)
    1581             :         {
    1582           0 :             ereport(LOG,
    1583             :                     (errcode_for_file_access(),
    1584             :                      errmsg("could not write file \"%s\": %m",
    1585             :                             LOG_METAINFO_DATAFILE_TMP)));
    1586           0 :             fclose(fh);
    1587           0 :             return;
    1588             :         }
    1589             :     }
    1590             : 
    1591           4 :     if (last_json_file_name && (Log_destination & LOG_DESTINATION_JSONLOG))
    1592             :     {
    1593           4 :         if (fprintf(fh, "jsonlog %s\n", last_json_file_name) < 0)
    1594             :         {
    1595           0 :             ereport(LOG,
    1596             :                     (errcode_for_file_access(),
    1597             :                      errmsg("could not write file \"%s\": %m",
    1598             :                             LOG_METAINFO_DATAFILE_TMP)));
    1599           0 :             fclose(fh);
    1600           0 :             return;
    1601             :         }
    1602             :     }
    1603           4 :     fclose(fh);
    1604             : 
    1605           4 :     if (rename(LOG_METAINFO_DATAFILE_TMP, LOG_METAINFO_DATAFILE) != 0)
    1606           0 :         ereport(LOG,
    1607             :                 (errcode_for_file_access(),
    1608             :                  errmsg("could not rename file \"%s\" to \"%s\": %m",
    1609             :                         LOG_METAINFO_DATAFILE_TMP, LOG_METAINFO_DATAFILE)));
    1610             : }
    1611             : 
    1612             : /* --------------------------------
    1613             :  *      signal handler routines
    1614             :  * --------------------------------
    1615             :  */
    1616             : 
    1617             : /*
    1618             :  * Check to see if a log rotation request has arrived.  Should be
    1619             :  * called by postmaster after receiving SIGUSR1.
    1620             :  */
    1621             : bool
    1622           2 : CheckLogrotateSignal(void)
    1623             : {
    1624             :     struct stat stat_buf;
    1625             : 
    1626           2 :     if (stat(LOGROTATE_SIGNAL_FILE, &stat_buf) == 0)
    1627           2 :         return true;
    1628             : 
    1629           0 :     return false;
    1630             : }
    1631             : 
    1632             : /*
    1633             :  * Remove the file signaling a log rotation request.
    1634             :  */
    1635             : void
    1636        1188 : RemoveLogrotateSignalFiles(void)
    1637             : {
    1638        1188 :     unlink(LOGROTATE_SIGNAL_FILE);
    1639        1188 : }
    1640             : 
    1641             : /* SIGUSR1: set flag to rotate logfile */
    1642             : static void
    1643           2 : sigUsr1Handler(SIGNAL_ARGS)
    1644             : {
    1645           2 :     int         save_errno = errno;
    1646             : 
    1647           2 :     rotation_requested = true;
    1648           2 :     SetLatch(MyLatch);
    1649             : 
    1650           2 :     errno = save_errno;
    1651           2 : }

Generated by: LCOV version 1.14