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