/*------------------------------------------------------------------------- * * syslogger.c * * The system logger (syslogger) is new in Postgres 7.5. It catches all * stderr output from backends, the postmaster and subprocesses by * redirecting to a pipe, and writes it to a logfile and stderr if * configured. * It's possible to have size and age limits for the logfile configured * in postgresql.conf. If these limits are reached or passed, the * current logfile is closed and a new one is created (rotated). * The logfiles are stored in a subdirectory (configurable in * postgresql.conf), using an internal naming scheme that mangles * creation time and current postmaster pid. * * Author: Andreas Pflug * * Copyright (c) 2004, PostgreSQL Global Development Group * * * IDENTIFICATION * $PostgreSQL: $ * *------------------------------------------------------------------------- */ #include "postgres.h" #include #include #include #include "libpq/pqsignal.h" #include "miscadmin.h" #include "postmaster/postmaster.h" #include "storage/pmsignal.h" #include "storage/pg_shmem.h" #include "storage/ipc.h" #include "postmaster/syslogger.h" #include "utils/ps_status.h" #include "utils/guc.h" /* * GUC parameters */ int Log_RotationAge = 24*60; int Log_RotationSize = 10*1024; char * Log_directory = "pg_log"; char * Log_filename_prefix = "postgresql-"; extern pid_t SysLoggerPID; /* * Flags set by interrupt handlers for later service in the main loop. */ static volatile sig_atomic_t got_SIGHUP = false; static volatile sig_atomic_t rotation_requested = false; #define MAXRETRIES 3 static pg_time_t last_rotation_time = 0; static char currentLogDir[MAXPGPATH]; static void sigHupHandler(SIGNAL_ARGS); static void rotationHandler(SIGNAL_ARGS); void writeLogfile(char *buffer, int count); #ifdef EXEC_BACKEND static pid_t syslogger_forkexec(void); #endif static char* logfile_getname(pg_time_t timestamp); static bool logfile_rotate(void); FILE *realStdErr = NULL; volatile FILE *syslogFile = NULL; #ifdef WIN32 static unsigned int __stdcall pipeThread(void *arg); static HANDLE readPipe=0, writePipe=0; static HANDLE threadHandle=0; static CRITICAL_SECTION sysfileSection; #else static int syslogPipe[2] = {0, 0}; #endif void writeLogfile(char *buffer, int count) { int rc; #ifdef WIN32 EnterCriticalSection(&sysfileSection); rc = fwrite(buffer, 1, count, (FILE*)syslogFile); LeaveCriticalSection(&sysfileSection); #else rc = fwrite(buffer, 1, count, (FILE*)syslogFile); #endif if (rc < 1) { ereport(COMMERROR, (errcode_for_file_access(), errmsg("fwrite to logfile failed in system logger: %m"))); exit(1); } if (Log_destination & LOG_DESTINATION_STDERR) { if (realStdErr) fwrite(buffer, 1, count, realStdErr); else fwrite(buffer, 1, count, stderr); } } #ifdef WIN32 unsigned int __stdcall pipeThread(void *arg) { DWORD bytesRead; char logbuffer[1024]; for (;;) { if (!ReadFile(readPipe, logbuffer, sizeof(logbuffer), &bytesRead, 0)) { ereport(COMMERROR, (errcode_for_file_access(), errmsg("could not read from system logger pipe: %m"))); exit(1); } if (bytesRead > 0) writeLogfile(logbuffer, bytesRead); } _endthread(); return 0; } #endif /* * Main entry point for syslogger process * argc/argv parameters are valid only in EXEC_BACKEND case. */ void SysLoggerMain(int argc, char *argv[]) { #ifdef EXEC_BACKEND int fd; Assert(argc == 8); argv += 3; strncpy(postgres_exec_path, *argv++, MAXPGPATH); #ifdef WIN32 readPipe = (HANDLE)atoi(*argv++); writePipe = (HANDLE)atoi(*argv++); fd = atoi(*argv++); if (fd != 0) fd = _open_osfhandle(fd, _O_APPEND); if (fd != 0) syslogFile = fdopen(fd, "a+"); fd = atoi(*argv++); if (fd != 0) fd = _open_osfhandle(fd, _O_APPEND); if (fd != 0) { realStdErr = fdopen(fd, "a"); setvbuf((FILE*)realStdErr, 0, _IONBF, 0); } InitializeCriticalSection(&sysfileSection); unsigned int tid; threadHandle = (HANDLE)_beginthreadex(0, 0, pipeThread, 0, 0, &tid); #else syslogPipe[0] = atoi(*argv++); syslogPipe[1] = atoi(*argv++); fd = atoi(*argv++); if (fd != 0) syslogFile = fdopen(fd, "a+"); fd = atoi(*argv++); if (fd != 0) { realStdErr = fdopen(fd, "a"); setvbuf((FILE*)realStdErr, 0, _IONBF, 0); } #endif #endif setvbuf((FILE*)syslogFile, 0, _IONBF, 0); IsUnderPostmaster = true; MyProcPid = getpid(); init_ps_display("system logger process", "", ""); set_ps_display(""); /* * Properly accept or ignore signals the postmaster might send us * * Note: we ignore all termination signals, and wait for the postmaster * to die to catch as much pipe output as possible. */ pqsignal(SIGHUP, sigHupHandler); /* set flag to read config file */ pqsignal(SIGINT, SIG_IGN); pqsignal(SIGTERM, SIG_IGN); pqsignal(SIGQUIT, SIG_IGN); pqsignal(SIGALRM, SIG_IGN); pqsignal(SIGPIPE, SIG_IGN); pqsignal(SIGUSR1, rotationHandler); /* request log rotation */ pqsignal(SIGUSR2, SIG_IGN); /* * Reset some signals that are accepted by postmaster but not here */ pqsignal(SIGCHLD, SIG_DFL); pqsignal(SIGTTIN, SIG_DFL); pqsignal(SIGTTOU, SIG_DFL); pqsignal(SIGCONT, SIG_DFL); pqsignal(SIGWINCH, SIG_DFL); PG_SETMASK(&UnBlockSig); /* * if we restarted, our stderr is redirected. * Direct it back to system stderr. */ if (realStdErr != NULL) { if (dup2(fileno(realStdErr), fileno(stderr)) < 0) { char *errstr = strerror(errno); /* * Now we have a real problem: we can't redirect to stderr, * and can't ereport it correctly (it would go into our queue * which will never be read * We're writing everywhere, hoping to leave at least some * hint of what happened. */ fprintf(realStdErr, "PANIC: Syslogger couldn't redirect its stderr to the saved stderr: %s\n", errstr); fprintf(stderr, "PANIC: Syslogger couldn't redirect its stderr to the saved stderr: %s\n", errstr); ereport(PANIC, (errcode_for_file_access(), (errmsg("Syslogger couldn't redirect its stderr to the saved stderr: %s", errstr)))); exit(1); } realStdErr = NULL; } /* remember age of initial logfile */ last_rotation_time = time(NULL); strncpy(currentLogDir, Log_directory, MAXPGPATH); /* main worker loop */ for (;;) { pg_time_t now; int elapsed_secs; #ifndef WIN32 char logbuffer[1024]; int bytesRead; int rc; fd_set rfds; struct timeval timeout; #endif if (got_SIGHUP) { got_SIGHUP = false; ProcessConfigFile(PGC_SIGHUP); /* * check if the log directory changed * in postgresql.conf. If so, we rotate to make sure * we're writing the logfiles where the backends * expect us to do so. */ if (strncmp(Log_directory, currentLogDir, MAXPGPATH)) { rotation_requested = true; strncpy(currentLogDir, Log_directory, MAXPGPATH); } } if (!rotation_requested && last_rotation_time != 0 && Log_RotationAge > 0) { /* * Do an unforced rotation if too much time has elapsed * since the last one. */ now = time(NULL); elapsed_secs = now - last_rotation_time; if (elapsed_secs >= Log_RotationAge * 60) rotation_requested = true; } if (!rotation_requested && Log_RotationSize > 0) { /* * Do an unforced rotation if file is too big */ if (ftell((FILE*)syslogFile) >= Log_RotationSize * 1024) rotation_requested = true; } if (rotation_requested) { if (!logfile_rotate()) { ereport(ERROR, (errcode_for_file_access(), (errmsg("logfile rotation failed, disabling auto rotation (SIGHUP to reenable): %m")))); Log_RotationAge = 0; Log_RotationSize = 0; } rotation_requested = false; } #ifdef WIN32 pgwin32_backend_usleep(1000000); #else FD_ZERO(&rfds); FD_SET(syslogPipe[0], &rfds); timeout.tv_sec=1; timeout.tv_usec=0; /* * Check if data is present */ rc = select(syslogPipe[0]+1, &rfds, NULL, NULL, &timeout); PG_SETMASK(&UnBlockSig); if (rc < 0 && errno != EINTR) { ereport(COMMERROR, (errcode_for_socket_access(), errmsg("select() failed in system logger: %m"))); exit(1); } if (rc > 0 && FD_ISSET(syslogPipe[0], &rfds)) { bytesRead = piperead(syslogPipe[0], logbuffer, sizeof(logbuffer)); if (bytesRead < 0 && errno != EINTR) { /* * EMFILE has been observed when a backend terminated * after a SSL client connection broke down. * There might be others we should ignore. */ if (errno == EMFILE) continue; ereport(COMMERROR, (errcode_for_socket_access(), errmsg("could not read from system logger pipe: %m"))); exit(1); } else if (bytesRead > 0) { writeLogfile(logbuffer, bytesRead); continue; } } #endif /* * If postmaster died, there's nothing to log any more. * We check this only after pipe timeouts to receive as much as possible * from the pipe. */ if (!PostmasterIsAlive(true)) { #ifdef WIN32 /* make sure the pipe is empty */ Sleep(100); SuspendThread(threadHandle); CloseHandle(threadHandle); #endif if (syslogFile) fclose((FILE*)syslogFile); exit(0); } } } int SysLogger_Start(void) { pid_t sysloggerPid; pg_time_t now; char *filename; if (!(Log_destination & LOG_DESTINATION_FILE)) return 0; /* create the pipe which will receive stderr output */ #ifdef WIN32 if (!readPipe) { SECURITY_ATTRIBUTES sa; memset(&sa, 0, sizeof(SECURITY_ATTRIBUTES)); sa.nLength = sizeof(SECURITY_ATTRIBUTES); sa.bInheritHandle = TRUE; if (!CreatePipe(&readPipe, &writePipe, &sa, 32768)) ereport(FATAL, (errcode_for_file_access(), (errmsg("pipe for syslogging not created: %m")))); #else if (!syslogPipe[0]) { if (pgpipe(syslogPipe) < 0) ereport(FATAL, (errcode_for_socket_access(), (errmsg("pipe for syslogging not created: %m")))); if (!set_noblock(syslogPipe[1])) { ereport(FATAL, (errcode_for_socket_access(), errmsg("could not set syslogging pipe to nonblocking mode: %m"))); } #endif } now = time(NULL); /* * create log directory, ignore error (will be caught on first logfile open) */ if (is_absolute_path(Log_directory)) mkdir(Log_directory, 0700); else { filename = palloc(MAXPGPATH); snprintf(filename, MAXPGPATH, "%s/%s", DataDir, Log_directory); mkdir(filename, 0700); pfree(filename); } /* * The initial logfile is created right in the postmaster, * to insure that the logger process has a writable file. */ filename = logfile_getname(now); /* * The file is opened for appending, in case the syslogger * is restarted right after a rotation. */ syslogFile = fopen(filename, "a+"); if (!syslogFile) { /* * if we can't open the syslog file for the syslogger process, * we try to redirect stderr back to have some logging. */ ereport(WARNING, (errcode_for_file_access(), (errmsg("error opening syslog file %s: %m", filename)))); if (realStdErr != NULL) { if (dup2(fileno(realStdErr), fileno(stderr)) < 0) ereport(FATAL, (errcode_for_file_access(), (errmsg("error redirecting stderr to default: %m")))); ereport(FATAL, (errmsg("logfile output corrupted"))); } } pfree(filename); fflush(stdout); fflush(stderr); #ifdef __BEOS__ /* Specific beos actions before backend startup */ beos_before_backend_startup(); #endif #ifdef EXEC_BACKEND switch ((sysloggerPid = syslogger_forkexec())) #else switch ((sysloggerPid = fork())) #endif { case -1: #ifdef __BEOS__ /* Specific beos actions */ beos_backend_startup_failed(); #endif ereport(LOG, (errmsg("could not fork system logger: %m"))); return 0; #ifndef EXEC_BACKEND case 0: /* in postmaster child ... */ #ifdef __BEOS__ /* Specific beos actions after backend startup */ beos_backend_startup(); #endif /* Close the postmaster's sockets */ ClosePostmasterPorts(); /* Drop our connection to postmaster's shared memory, as well */ PGSharedMemoryDetach(); /* do the work */ SysLoggerMain(0, NULL); break; #endif default: /* now we redirect stderr, if not done already */ if (realStdErr == NULL) { int dh= dup(fileno(stderr)); if (dh < 0) ereport(FATAL, (errcode_for_file_access(), (errmsg("stderr duplication failed: %m")))); realStdErr = fdopen(dh, "a"); if (realStdErr == NULL) ereport(FATAL, (errcode_for_file_access(), (errmsg("realstderr reopen failed: %m")))); #ifdef WIN32 if (dup2(_open_osfhandle((long)writePipe, _O_APPEND), _fileno(stderr)) < 0) ereport(FATAL, (errcode_for_file_access(), (errmsg("stderr pipe redirection failed: %m")))); #else if (dup2(syslogPipe[1], fileno(stdout)) < 0) ereport(FATAL, (errcode_for_file_access(), (errmsg("stdout pipe redirection failed: %m")))); if (dup2(syslogPipe[1], fileno(stderr)) < 0) ereport(FATAL, (errcode_for_file_access(), (errmsg("stderr pipe redirection failed: %m")))); #endif } /* postmaster will never write the file; close it */ fclose((FILE*)syslogFile); syslogFile = NULL; return (int) sysloggerPid; } /* we should never reach here */ return 0; } #ifdef EXEC_BACKEND static pid_t syslogger_forkexec() { char *av[10]; int ac = 0, bufc = 0, i; char numbuf[4][32]; av[ac++] = "postgres"; av[ac++] = "-forklog"; av[ac++] = NULL; /* filled in by postmaster_forkexec */ /* postgres_exec_path is not passed by write_backend_variables */ av[ac++] = postgres_exec_path; /* Pipe file ids (those not passed by write_backend_variables) */ #ifdef WIN32 snprintf(numbuf[bufc++], 32, "%d", (int)readPipe); snprintf(numbuf[bufc++], 32, "%d", (int)writePipe); if (syslogFile != 0) snprintf(numbuf[bufc++], 32, "%ld", _get_osfhandle(_fileno((FILE*)syslogFile))); else strcpy(numbuf[bufc++], "0"); if (realStdErr != 0) snprintf(numbuf[bufc++],32, "%ld", _get_osfhandle(_fileno(realStdErr))); else strcpy(numbuf[bufc++], "0"); #else snprintf(numbuf[bufc++],32, "%d", syslogPipe[0]); snprintf(numbuf[bufc++],32, "%d", syslogPipe[1]); if (syslogFile != 0) snprintf(numbuf[bufc++], 32, "%d", fileno(syslogFile))); else strcpy(numbuf[bufc++], "0"); if (realStdErr != 0) snprintf(numbuf[bufc++], 32, "%d", fileno(realStdErr))); else strcpy(numbuf[bufc++], "0"); #endif /* Add to the arg list */ Assert(bufc <= lengthof(pgstatBuf)); for (i = 0; i < bufc; i++) av[ac++] = numbuf[i]; av[ac] = NULL; Assert(ac < lengthof(av)); return postmaster_forkexec(ac, av); } #endif /* -------------------------------- * logfile routines * -------------------------------- */ /* * perform rotation */ bool logfile_rotate(void) { char *filename; pg_time_t now; FILE *fh; now = time(NULL); filename = logfile_getname(now); fh = fopen(filename, "a+"); if (!fh) { /* * if opening the new file fails, the caller is responsible * for taking consequences. */ pfree(filename); return false; } setvbuf(fh, 0, _IONBF, 0); #ifdef WIN32 EnterCriticalSection(&sysfileSection); fclose((FILE*)syslogFile); syslogFile = fh; LeaveCriticalSection(&sysfileSection); #else fclose(syslogFile); syslogFile = fh; #endif last_rotation_time = now; /* official opening of the new logfile */ ereport(NOTICE, (errcode(ERRCODE_WARNING), errmsg("Opened new log file %s", filename))); pfree(filename); return true; } /* * creates logfile name using timestamp information */ #define TIMESTAMPPATTERN "%Y-%m-%d_%H%M%S" static char* logfile_getname(pg_time_t timestamp) { char *filetemplate; char *filename; if (is_absolute_path(Log_directory)) { filetemplate = palloc(strlen(Log_directory) + strlen(Log_filename_prefix) + sizeof(TIMESTAMPPATTERN)+10 +2); if (filetemplate) sprintf(filetemplate, "%s/%s%s_%05lu.log", Log_directory, Log_filename_prefix, TIMESTAMPPATTERN, (unsigned long)PostmasterPid); } else { filetemplate = palloc(strlen(DataDir) + strlen(Log_directory) + strlen(Log_filename_prefix) + sizeof(TIMESTAMPPATTERN) +10 +3); if (filetemplate) sprintf(filetemplate, "%s/%s/%s%s_%05lu.log", DataDir, Log_directory, Log_filename_prefix, TIMESTAMPPATTERN, (unsigned long)PostmasterPid); } filename = palloc(MAXPGPATH); if (!filename || !filetemplate) ereport(FATAL, (errcode(ERRCODE_OUT_OF_MEMORY), errmsg("Out of memory"))); pg_strftime(filename, MAXPGPATH, filetemplate, pg_localtime(×tamp)); pfree(filetemplate); return filename; } /* -------------------------------- * API helper routines * -------------------------------- */ /* * Rotate log file */ bool LogFileRotate(void) { if (!(Log_destination & LOG_DESTINATION_FILE)) { ereport(NOTICE, (errcode(ERRCODE_WARNING), errmsg("no logfile configured; rotation not supported"))); return false; } SendPostmasterSignal(PMSIGNAL_ROTATE_LOGFILE); return true; } /* -------------------------------- * signal handler routines * -------------------------------- */ /* SIGHUP: set flag to reload config file */ static void sigHupHandler(SIGNAL_ARGS) { got_SIGHUP = true; } /* SIGUSR1: set flag to rotate logfile */ static void rotationHandler(SIGNAL_ARGS) { rotation_requested = true; }