TLA 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 CBC 1 : SysLoggerMain(int argc, char *argv[])
166 : {
167 : #ifndef WIN32
168 : char logbuffer[READ_BUF_SIZE];
169 1 : 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 1 : now = MyStartTime;
178 :
179 : #ifdef EXEC_BACKEND
180 : syslogger_parseArgs(argc, argv);
181 : #endif /* EXEC_BACKEND */
182 :
183 1 : MyBackendType = B_LOGGER;
184 1 : 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 1 : if (redirection_done)
194 : {
195 UBC 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 CBC 1 : if (syslogPipe[1] >= 0)
235 1 : close(syslogPipe[1]);
236 1 : 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 1 : pqsignal(SIGHUP, SignalHandlerForConfigReload); /* set flag to read config
252 : * file */
253 1 : pqsignal(SIGINT, SIG_IGN);
254 1 : pqsignal(SIGTERM, SIG_IGN);
255 1 : pqsignal(SIGQUIT, SIG_IGN);
256 1 : pqsignal(SIGALRM, SIG_IGN);
257 1 : pqsignal(SIGPIPE, SIG_IGN);
258 1 : pqsignal(SIGUSR1, sigUsr1Handler); /* request log rotation */
259 1 : pqsignal(SIGUSR2, SIG_IGN);
260 :
261 : /*
262 : * Reset some signals that are accepted by postmaster but not here
263 : */
264 1 : pqsignal(SIGCHLD, SIG_DFL);
265 :
266 GNC 1 : 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 CBC 1 : last_sys_file_name = logfile_getname(first_syslogger_file_time, NULL);
284 1 : if (csvlogFile != NULL)
285 1 : last_csv_file_name = logfile_getname(first_syslogger_file_time, ".csv");
286 1 : if (jsonlogFile != NULL)
287 1 : last_json_file_name = logfile_getname(first_syslogger_file_time, ".json");
288 :
289 : /* remember active logfile parameters */
290 1 : currentLogDir = pstrdup(Log_directory);
291 1 : currentLogFilename = pstrdup(Log_filename);
292 1 : currentLogRotationAge = Log_RotationAge;
293 : /* set next planned rotation time */
294 1 : set_next_rotation_time();
295 1 : 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 1 : 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 1 : wes = CreateWaitEventSet(CurrentMemoryContext, 2);
315 1 : AddWaitEventToSet(wes, WL_LATCH_SET, PGINVALID_SOCKET, MyLatch, NULL);
316 : #ifndef WIN32
317 1 : AddWaitEventToSet(wes, WL_SOCKET_READABLE, syslogPipe[0], NULL, NULL);
318 : #endif
319 :
320 : /* main worker loop */
321 : for (;;)
322 32 : {
323 33 : bool time_based_rotation = false;
324 33 : 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 33 : ResetLatch(MyLatch);
334 :
335 : /*
336 : * Process any requests or signals received recently.
337 : */
338 33 : if (ConfigReloadPending)
339 : {
340 UBC 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 CBC 33 : if (Log_RotationAge > 0 && !rotation_disabled)
411 : {
412 : /* Do a logfile rotation if it's time */
413 UBC 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 CBC 33 : if (!rotation_requested && Log_RotationSize > 0 && !rotation_disabled)
419 : {
420 : /* Do a rotation if file is too big */
421 32 : if (ftell(syslogFile) >= Log_RotationSize * 1024L)
422 : {
423 UBC 0 : rotation_requested = true;
424 0 : size_rotation_for |= LOG_DESTINATION_STDERR;
425 : }
426 CBC 32 : if (csvlogFile != NULL &&
427 32 : ftell(csvlogFile) >= Log_RotationSize * 1024L)
428 : {
429 UBC 0 : rotation_requested = true;
430 0 : size_rotation_for |= LOG_DESTINATION_CSVLOG;
431 : }
432 CBC 32 : if (jsonlogFile != NULL &&
433 32 : ftell(jsonlogFile) >= Log_RotationSize * 1024L)
434 : {
435 UBC 0 : rotation_requested = true;
436 0 : size_rotation_for |= LOG_DESTINATION_JSONLOG;
437 : }
438 : }
439 :
440 CBC 33 : 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 1 : if (!time_based_rotation && size_rotation_for == 0)
447 1 : size_rotation_for = LOG_DESTINATION_STDERR |
448 : LOG_DESTINATION_CSVLOG |
449 : LOG_DESTINATION_JSONLOG;
450 1 : 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 33 : if (Log_RotationAge > 0 && !rotation_disabled)
466 UBC 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 CBC 33 : cur_timeout = -1L;
481 :
482 : /*
483 : * Sleep until there's something to do
484 : */
485 : #ifndef WIN32
486 33 : rc = WaitEventSetWait(wes, cur_timeout, &event, 1,
487 : WAIT_EVENT_SYSLOGGER_MAIN);
488 :
489 33 : if (rc == 1 && event.events == WL_SOCKET_READABLE)
490 : {
491 : int bytesRead;
492 :
493 32 : bytesRead = read(syslogPipe[0],
494 : logbuffer + bytes_in_logbuffer,
495 : sizeof(logbuffer) - bytes_in_logbuffer);
496 32 : if (bytesRead < 0)
497 : {
498 UBC 0 : if (errno != EINTR)
499 0 : ereport(LOG,
500 : (errcode_for_socket_access(),
501 : errmsg("could not read from logger pipe: %m")));
502 : }
503 CBC 32 : else if (bytesRead > 0)
504 : {
505 31 : bytes_in_logbuffer += bytesRead;
506 31 : process_pipe_input(logbuffer, &bytes_in_logbuffer);
507 31 : 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 1 : pipe_eof_seen = true;
518 :
519 : /* if there's any data left then force it out now */
520 1 : 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 2 : 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 1 : 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 1 : proc_exit(0);
559 : }
560 : }
561 : }
562 :
563 : /*
564 : * Postmaster subroutine to start a syslogger subprocess.
565 : */
566 : int
567 593 : SysLogger_Start(void)
568 : {
569 : pid_t sysloggerPid;
570 : char *filename;
571 :
572 593 : if (!Logging_collector)
573 592 : 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 1 : if (syslogPipe[0] < 0)
594 : {
595 1 : if (pipe(syslogPipe) < 0)
596 UBC 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 CBC 1 : (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 1 : first_syslogger_file_time = time(NULL);
634 :
635 1 : filename = logfile_getname(first_syslogger_file_time, NULL);
636 :
637 1 : syslogFile = logfile_open(filename, "a", false);
638 :
639 1 : 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 1 : if (Log_destination & LOG_DESTINATION_CSVLOG)
647 : {
648 1 : filename = logfile_getname(first_syslogger_file_time, ".csv");
649 :
650 1 : csvlogFile = logfile_open(filename, "a", false);
651 :
652 1 : 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 1 : if (Log_destination & LOG_DESTINATION_JSONLOG)
661 : {
662 1 : filename = logfile_getname(first_syslogger_file_time, ".json");
663 :
664 1 : jsonlogFile = logfile_open(filename, "a", false);
665 :
666 1 : pfree(filename);
667 : }
668 :
669 : #ifdef EXEC_BACKEND
670 : switch ((sysloggerPid = syslogger_forkexec()))
671 : #else
672 1 : switch ((sysloggerPid = fork_process()))
673 : #endif
674 : {
675 UBC 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 CBC 1 : case 0:
682 : /* in postmaster child ... */
683 1 : InitPostmasterChild();
684 :
685 : /* Close the postmaster's sockets */
686 1 : ClosePostmasterPorts(true);
687 :
688 : /* Drop our connection to postmaster's shared memory, as well */
689 1 : dsm_detach_all();
690 1 : PGSharedMemoryDetach();
691 :
692 : /* do the work */
693 1 : SysLoggerMain(0, NULL);
694 : break;
695 : #endif
696 :
697 1 : default:
698 : /* success, in postmaster */
699 :
700 : /* now we redirect stderr, if not done already */
701 1 : 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 1 : 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 1 : fflush(stdout);
719 1 : if (dup2(syslogPipe[1], STDOUT_FILENO) < 0)
720 UBC 0 : ereport(FATAL,
721 : (errcode_for_file_access(),
722 : errmsg("could not redirect stdout: %m")));
723 CBC 1 : fflush(stderr);
724 1 : if (dup2(syslogPipe[1], STDERR_FILENO) < 0)
725 UBC 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 CBC 1 : close(syslogPipe[1]);
730 1 : 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 1 : redirection_done = true;
756 : }
757 :
758 : /* postmaster will never write the file(s); close 'em */
759 1 : fclose(syslogFile);
760 1 : syslogFile = NULL;
761 1 : if (csvlogFile != NULL)
762 : {
763 1 : fclose(csvlogFile);
764 1 : csvlogFile = NULL;
765 : }
766 1 : if (jsonlogFile != NULL)
767 : {
768 1 : fclose(jsonlogFile);
769 1 : jsonlogFile = NULL;
770 : }
771 1 : 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 31 : process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
930 : {
931 31 : char *cursor = logbuffer;
932 31 : int count = *bytes_in_logbuffer;
933 31 : int dest = LOG_DESTINATION_STDERR;
934 :
935 : /* While we have enough for a header, process data... */
936 91 : 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 60 : memcpy(&p, cursor, offsetof(PipeProtoHeader, data));
944 60 : dest_flags = p.flags & (PIPE_PROTO_DEST_STDERR |
945 : PIPE_PROTO_DEST_CSVLOG |
946 : PIPE_PROTO_DEST_JSONLOG);
947 60 : if (p.nuls[0] == '\0' && p.nuls[1] == '\0' &&
948 60 : p.len > 0 && p.len <= PIPE_MAX_PAYLOAD &&
949 120 : p.pid != 0 &&
950 60 : pg_popcount((char *) &dest_flags, 1) == 1)
951 60 : {
952 : List *buffer_list;
953 : ListCell *cell;
954 60 : save_buffer *existing_slot = NULL,
955 60 : *free_slot = NULL;
956 : StringInfo str;
957 :
958 60 : chunklen = PIPE_HEADER_SIZE + p.len;
959 :
960 : /* Fall out of loop if we don't have the whole chunk yet */
961 60 : if (count < chunklen)
962 UBC 0 : break;
963 :
964 CBC 60 : if ((p.flags & PIPE_PROTO_DEST_STDERR) != 0)
965 20 : dest = LOG_DESTINATION_STDERR;
966 40 : else if ((p.flags & PIPE_PROTO_DEST_CSVLOG) != 0)
967 20 : dest = LOG_DESTINATION_CSVLOG;
968 20 : else if ((p.flags & PIPE_PROTO_DEST_JSONLOG) != 0)
969 20 : dest = LOG_DESTINATION_JSONLOG;
970 : else
971 : {
972 : /* this should never happen as of the header validation */
973 UBC 0 : Assert(false);
974 : }
975 :
976 : /* Locate any existing buffer for this source pid */
977 CBC 60 : buffer_list = buffer_lists[p.pid % NBUFFER_LISTS];
978 60 : foreach(cell, buffer_list)
979 : {
980 UBC 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 CBC 60 : if ((p.flags & PIPE_PROTO_IS_LAST) == 0)
992 : {
993 : /*
994 : * Save a complete non-final chunk in a per-pid buffer
995 : */
996 UBC 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 CBC 60 : if (existing_slot != NULL)
1032 : {
1033 UBC 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 CBC 60 : write_syslogger_file(cursor + PIPE_HEADER_SIZE, p.len,
1046 : dest);
1047 : }
1048 : }
1049 :
1050 : /* Finished processing this chunk */
1051 60 : cursor += chunklen;
1052 60 : 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 UBC 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 CBC 31 : if (count > 0 && cursor != logbuffer)
1081 UBC 0 : memmove(logbuffer, cursor, count);
1082 CBC 31 : *bytes_in_logbuffer = count;
1083 31 : }
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 1 : flush_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
1093 : {
1094 : int i;
1095 :
1096 : /* Dump any incomplete protocol messages */
1097 257 : for (i = 0; i < NBUFFER_LISTS; i++)
1098 : {
1099 256 : List *list = buffer_lists[i];
1100 : ListCell *cell;
1101 :
1102 256 : foreach(cell, list)
1103 : {
1104 UBC 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 CBC 1 : if (*bytes_in_logbuffer > 0)
1124 UBC 0 : write_syslogger_file(logbuffer, *bytes_in_logbuffer,
1125 : LOG_DESTINATION_STDERR);
1126 CBC 1 : *bytes_in_logbuffer = 0;
1127 1 : }
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 60 : 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 60 : if ((destination & LOG_DESTINATION_CSVLOG) && csvlogFile != NULL)
1162 20 : logfile = csvlogFile;
1163 40 : else if ((destination & LOG_DESTINATION_JSONLOG) && jsonlogFile != NULL)
1164 20 : logfile = jsonlogFile;
1165 : else
1166 20 : logfile = syslogFile;
1167 :
1168 60 : 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 60 : if (rc != count)
1177 UBC 0 : write_stderr("could not write to log file: %s\n", strerror(errno));
1178 CBC 60 : }
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 6 : 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 6 : oumask = umask((mode_t) ((~(Log_file_mode | S_IWUSR)) & (S_IRWXU | S_IRWXG | S_IRWXO)));
1277 6 : fh = fopen(filename, mode);
1278 6 : umask(oumask);
1279 :
1280 6 : if (fh)
1281 : {
1282 6 : 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 UBC 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 CBC 6 : 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 3 : 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 3 : 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 3 : if ((Log_destination & target_dest) == 0 &&
1327 : target_dest != LOG_DESTINATION_STDERR)
1328 : {
1329 UBC 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 CBC 3 : if (!time_based_rotation && (size_rotation_for & target_dest) == 0)
1343 UBC 0 : return true;
1344 :
1345 : /* file extension depends on the destination type */
1346 CBC 3 : if (target_dest == LOG_DESTINATION_STDERR)
1347 1 : logFileExt = NULL;
1348 2 : else if (target_dest == LOG_DESTINATION_CSVLOG)
1349 1 : logFileExt = ".csv";
1350 1 : else if (target_dest == LOG_DESTINATION_JSONLOG)
1351 1 : logFileExt = ".json";
1352 : else
1353 : {
1354 : /* cannot happen */
1355 UBC 0 : Assert(false);
1356 : }
1357 :
1358 : /* build the new file name */
1359 CBC 3 : 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 3 : if (Log_truncate_on_rotation && time_based_rotation &&
1368 UBC 0 : *last_file_name != NULL &&
1369 0 : strcmp(filename, *last_file_name) != 0)
1370 0 : fh = logfile_open(filename, "w", true);
1371 : else
1372 CBC 3 : fh = logfile_open(filename, "a", true);
1373 :
1374 3 : 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 UBC 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 CBC 3 : if (*logFile != NULL)
1396 3 : fclose(*logFile);
1397 3 : *logFile = fh;
1398 :
1399 : /* instead of pfree'ing filename, remember it for next time */
1400 3 : if (*last_file_name != NULL)
1401 3 : pfree(*last_file_name);
1402 3 : *last_file_name = filename;
1403 :
1404 3 : return true;
1405 : }
1406 :
1407 : /*
1408 : * perform logfile rotation
1409 : */
1410 : static void
1411 1 : logfile_rotate(bool time_based_rotation, int size_rotation_for)
1412 : {
1413 : pg_time_t fntime;
1414 :
1415 1 : 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 1 : if (time_based_rotation)
1423 UBC 0 : fntime = next_rotation_time;
1424 : else
1425 CBC 1 : fntime = time(NULL);
1426 :
1427 : /* file rotation for stderr */
1428 1 : if (!logfile_rotate_dest(time_based_rotation, size_rotation_for, fntime,
1429 : LOG_DESTINATION_STDERR, &last_sys_file_name,
1430 : &syslogFile))
1431 UBC 0 : return;
1432 :
1433 : /* file rotation for csvlog */
1434 CBC 1 : if (!logfile_rotate_dest(time_based_rotation, size_rotation_for, fntime,
1435 : LOG_DESTINATION_CSVLOG, &last_csv_file_name,
1436 : &csvlogFile))
1437 UBC 0 : return;
1438 :
1439 : /* file rotation for jsonlog */
1440 CBC 1 : if (!logfile_rotate_dest(time_based_rotation, size_rotation_for, fntime,
1441 : LOG_DESTINATION_JSONLOG, &last_json_file_name,
1442 : &jsonlogFile))
1443 UBC 0 : return;
1444 :
1445 CBC 1 : update_metainfo_datafile();
1446 :
1447 1 : 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 9 : logfile_getname(pg_time_t timestamp, const char *suffix)
1461 : {
1462 : char *filename;
1463 : int len;
1464 :
1465 9 : filename = palloc(MAXPGPATH);
1466 :
1467 9 : snprintf(filename, MAXPGPATH, "%s/", Log_directory);
1468 :
1469 9 : len = strlen(filename);
1470 :
1471 : /* treat Log_filename as a strftime pattern */
1472 9 : pg_strftime(filename + len, MAXPGPATH - len, Log_filename,
1473 9 : pg_localtime(×tamp, log_timezone));
1474 :
1475 9 : if (suffix != NULL)
1476 : {
1477 6 : len = strlen(filename);
1478 6 : if (len > 4 && (strcmp(filename + (len - 4), ".log") == 0))
1479 6 : len -= 4;
1480 6 : strlcpy(filename + len, suffix, MAXPGPATH - len);
1481 : }
1482 :
1483 9 : return filename;
1484 : }
1485 :
1486 : /*
1487 : * Determine the next planned rotation time, and store in next_rotation_time.
1488 : */
1489 : static void
1490 2 : 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 2 : if (Log_RotationAge <= 0)
1498 2 : 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 UBC 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 CBC 2 : update_metainfo_datafile(void)
1526 : {
1527 : FILE *fh;
1528 : mode_t oumask;
1529 :
1530 2 : if (!(Log_destination & LOG_DESTINATION_STDERR) &&
1531 UBC 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 CBC 2 : oumask = umask(pg_mode_mask);
1544 2 : fh = fopen(LOG_METAINFO_DATAFILE_TMP, "w");
1545 2 : umask(oumask);
1546 :
1547 2 : if (fh)
1548 : {
1549 2 : 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 UBC 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 CBC 2 : if (last_sys_file_name && (Log_destination & LOG_DESTINATION_STDERR))
1566 : {
1567 2 : if (fprintf(fh, "stderr %s\n", last_sys_file_name) < 0)
1568 : {
1569 UBC 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 CBC 2 : if (last_csv_file_name && (Log_destination & LOG_DESTINATION_CSVLOG))
1579 : {
1580 2 : if (fprintf(fh, "csvlog %s\n", last_csv_file_name) < 0)
1581 : {
1582 UBC 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 CBC 2 : if (last_json_file_name && (Log_destination & LOG_DESTINATION_JSONLOG))
1592 : {
1593 2 : if (fprintf(fh, "jsonlog %s\n", last_json_file_name) < 0)
1594 : {
1595 UBC 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 CBC 2 : fclose(fh);
1604 :
1605 2 : if (rename(LOG_METAINFO_DATAFILE_TMP, LOG_METAINFO_DATAFILE) != 0)
1606 UBC 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 CBC 1 : CheckLogrotateSignal(void)
1623 : {
1624 : struct stat stat_buf;
1625 :
1626 1 : if (stat(LOGROTATE_SIGNAL_FILE, &stat_buf) == 0)
1627 1 : return true;
1628 :
1629 UBC 0 : return false;
1630 : }
1631 :
1632 : /*
1633 : * Remove the file signaling a log rotation request.
1634 : */
1635 : void
1636 CBC 594 : RemoveLogrotateSignalFiles(void)
1637 : {
1638 594 : unlink(LOGROTATE_SIGNAL_FILE);
1639 594 : }
1640 :
1641 : /* SIGUSR1: set flag to rotate logfile */
1642 : static void
1643 1 : sigUsr1Handler(SIGNAL_ARGS)
1644 : {
1645 1 : int save_errno = errno;
1646 :
1647 1 : rotation_requested = true;
1648 1 : SetLatch(MyLatch);
1649 :
1650 1 : errno = save_errno;
1651 1 : }
|
