1 /*-------------------------------------------------------------------------
6 * Portions Copyright (c) 1996-2000, PostgreSQL, Inc
7 * Portions Copyright (c) 1994, Regents of the University of California
11 * $Header: /cvsroot/pgsql/src/backend/utils/error/elog.c,v 1.61 2000/06/28 03:32:27 tgl Exp $
13 *-------------------------------------------------------------------------
23 #include <sys/types.h>
33 #include "libpq/libpq.h"
34 #include "libpq/pqformat.h"
35 #include "miscadmin.h"
36 #include "storage/proc.h"
37 #include "tcop/tcopprot.h"
38 #include "commands/copy.h"
43 extern CommandDest whereToSendOutput;
47 * 0 = only stdout/stderr
48 * 1 = stdout+stderr and syslog
50 * ... in theory anyway
54 static void write_syslog(int level, const char *line);
63 #define TIMESTAMP_SIZE 20 /* format `YYYY-MM-DD HH:MM:SS ' */
64 #define PID_SIZE 9 /* format `[123456] ' */
66 static const char * print_timestamp(void);
67 static const char * print_pid(void);
69 static int Debugfile = -1;
70 static int Err_file = -1;
71 static int ElogDebugIndentLevel = 0;
73 /*--------------------
75 * Primary error logging function.
77 * 'lev': error level; indicates recovery action to take, if any.
78 * 'fmt': a printf-style string.
79 * Additional arguments, if any, are formatted per %-escapes in 'fmt'.
81 * In addition to the usual %-escapes recognized by printf, "%m" in
82 * fmt is replaced by the error message for the current value of errno.
84 * Note: no newline is needed at the end of the fmt string, since
85 * elog will provide one for the output methods that need it.
87 * If 'lev' is ERROR or worse, control does not return to the caller.
88 * See elog.h for the error level definitions.
92 elog(int lev, const char *fmt, ...)
96 * The expanded format and final output message are dynamically
97 * allocated if necessary, but not if they fit in the "reasonable
98 * size" buffers shown here. In extremis, we'd rather depend on
99 * having a few hundred bytes of stack space than on malloc() still
100 * working (since memory-clobber errors often take out malloc first).
101 * Don't make these buffers unreasonably large though, on pain of
102 * having to chase a bug with no error message.
104 * Note that we use malloc() not palloc() because we want to retain
105 * control if we run out of memory. palloc() would recursively call
106 * elog(ERROR), which would be all right except if we are working on a
107 * FATAL or REALLYFATAL error. We'd lose track of the fatal condition
108 * and report a mere ERROR to outer loop, which would be a Bad Thing.
109 * So, we substitute an appropriate message in-place, without downgrading
110 * the level if it's above ERROR.
112 char fmt_fixedbuf[128];
113 char msg_fixedbuf[256];
114 char *fmt_buf = fmt_fixedbuf;
115 char *msg_buf = msg_fixedbuf;
116 /* this buffer is only used for strange values of lev: */
118 /* this buffer is only used if errno has a bogus value: */
119 char errorstr_buf[32];
120 const char *errorstr;
127 /* size of the prefix needed for timestamp and pid, if enabled */
128 size_t timestamp_size;
130 if (lev <= DEBUG && Debugfile < 0)
131 return; /* ignore debug msgs if noplace to send */
133 /* save errno string for %m */
134 if (errno < sys_nerr && errno >= 0)
135 errorstr = strerror(errno);
138 sprintf(errorstr_buf, "error %d", errno);
139 errorstr = errorstr_buf;
142 if (lev == ERROR || lev == FATAL)
144 /* this is probably redundant... */
145 if (IsInitProcessingMode())
149 /* choose message prefix and indent level */
153 indent = ElogDebugIndentLevel - 1;
157 indent = indent % 30;
161 indent = ElogDebugIndentLevel;
165 indent = indent % 30;
175 sprintf(prefix_buf, "FATAL %d: ", lev);
182 timestamp_size += TIMESTAMP_SIZE;
184 timestamp_size += PID_SIZE;
187 * Set up the expanded format, consisting of the prefix string plus
188 * input format, with any %m replaced by strerror() string (since
189 * vsnprintf won't know what to do with %m). To keep space
190 * calculation simple, we only allow one %m.
192 space_needed = timestamp_size + strlen(prefix) + indent + (lineno ? 24 : 0)
193 + strlen(fmt) + strlen(errorstr) + 1;
194 if (space_needed > (int) sizeof(fmt_fixedbuf))
196 fmt_buf = (char *) malloc(space_needed);
199 /* We're up against it, convert to out-of-memory error */
200 fmt_buf = fmt_fixedbuf;
206 fmt = "elog: out of memory"; /* this must fit in
214 strcat(fmt_buf, print_timestamp());
216 strcat(fmt_buf, print_pid());
218 strcat(fmt_buf, prefix);
220 bp = fmt_buf + strlen(fmt_buf);
224 /* If error was in CopyFrom() print the offending line number -- dz */
227 sprintf(bp, "copy: line %d, ", lineno);
229 if (lev == ERROR || lev >= FATAL)
233 for (cp = fmt; *cp; cp++)
235 if (cp[0] == '%' && cp[1] != '\0')
241 * XXX If there are any %'s in errorstr then vsnprintf
242 * will do the Wrong Thing; do we need to cope? Seems
243 * unlikely that % would appear in system errors.
245 strcpy(bp, errorstr);
248 * copy the rest of fmt literally, since we can't afford
249 * to insert another %m.
257 /* copy % and next char --- this avoids trouble with %%m */
268 * Now generate the actual output text using vsnprintf(). Be sure to
269 * leave space for \n added later as well as trailing null.
271 space_needed = sizeof(msg_fixedbuf);
277 nprinted = vsnprintf(msg_buf, space_needed - 2, fmt_buf, ap);
281 * Note: some versions of vsnprintf return the number of chars
282 * actually stored, but at least one returns -1 on failure. Be
283 * conservative about believing whether the print worked.
285 if (nprinted >= 0 && nprinted < space_needed - 3)
287 /* It didn't work, try to get a bigger buffer */
288 if (msg_buf != msg_fixedbuf)
291 msg_buf = (char *) malloc(space_needed);
294 /* We're up against it, convert to out-of-memory error */
295 msg_buf = msg_fixedbuf;
303 strcat(msg_buf, print_timestamp());
305 strcat(msg_buf, print_pid());
306 strcat(msg_buf, prefix);
307 strcat(msg_buf, "elog: out of memory");
313 * Message prepared; send it where it should go
324 syslog_level = LOG_DEBUG;
327 syslog_level = LOG_DEBUG;
330 syslog_level = LOG_NOTICE;
333 syslog_level = LOG_WARNING;
336 syslog_level = LOG_ERR;
340 syslog_level = LOG_CRIT;
343 write_syslog(syslog_level, msg_buf + timestamp_size);
345 #endif /* ENABLE_SYSLOG */
347 /* syslog doesn't want a trailing newline, but other destinations do */
348 strcat(msg_buf, "\n");
350 len = strlen(msg_buf);
352 if (Debugfile >= 0 && Use_syslog <= 1)
353 write(Debugfile, msg_buf, len);
356 * If there's an error log file other than our channel to the
357 * front-end program, write to it first. This is important because
358 * there's a bug in the socket code on ultrix. If the front end has
359 * gone away (so the channel to it has been closed at the other end),
360 * then writing here can cause this backend to exit without warning
361 * that is, write() does an exit(). In this case, our only hope of
362 * finding out what's going on is if Err_file was set to some disk
363 * log. This is a major pain. (It's probably also long-dead code...
364 * does anyone still use ultrix?)
366 if (lev > DEBUG && Err_file >= 0 &&
367 Debugfile != Err_file && Use_syslog <= 1)
369 if (write(Err_file, msg_buf, len) < 0)
371 write(open("/dev/console", O_WRONLY, 0666), msg_buf, len);
377 #ifndef PG_STANDALONE
379 if (lev > DEBUG && whereToSendOutput == Remote)
381 /* Send IPC message to the front-end program */
390 * Abort any COPY OUT in progress when an error is detected.
391 * This hack is necessary because of poor design of copy
397 /* exclude the timestamp from msg sent to frontend */
398 pq_puttextmessage(msgtype, msg_buf + timestamp_size);
401 * This flush is normally not necessary, since postgres.c will
402 * flush out waiting data when control returns to the main loop.
403 * But it seems best to leave it here, so that the client has some
404 * clue what happened if the backend dies before getting back to
405 * the main loop ... error/notice messages should not be a
406 * performance-critical path anyway, so an extra flush won't hurt
412 if (lev > DEBUG && whereToSendOutput != Remote)
416 * We are running as an interactive backend, so just send the
419 fputs(msg_buf, stderr);
422 #endif /* !PG_STANDALONE */
424 /* done with the message, release space */
425 if (fmt_buf != fmt_fixedbuf)
427 if (msg_buf != msg_fixedbuf)
431 * Perform error recovery action as specified by lev.
433 if (lev == ERROR || lev == FATAL)
437 * If we have not yet entered the main backend loop (ie, we are in
438 * the postmaster or in backend startup), then go directly to
439 * proc_exit. The same is true if anyone tries to report an error
440 * after proc_exit has begun to run. (It's proc_exit's
441 * responsibility to see that this doesn't turn into infinite
442 * recursion!) But in the latter case, we exit with nonzero exit
443 * code to indicate that something's pretty wrong.
445 if (proc_exit_inprogress || !Warn_restart_ready)
449 ProcReleaseSpins(NULL); /* get rid of spinlocks we hold */
450 ProcReleaseLocks(); /* get rid of real locks we hold */
451 /* XXX shouldn't proc_exit be doing the above?? */
452 proc_exit((int) proc_exit_inprogress);
456 * Guard against infinite loop from elog() during error recovery.
459 elog(REALLYFATAL, "elog: error during error recovery, giving up!");
463 * Otherwise we can return to the main loop in postgres.c. In the
464 * FATAL case, postgres.c will call proc_exit, but not till after
465 * completing a standard transaction-abort sequence.
467 ProcReleaseSpins(NULL); /* get rid of spinlocks we hold */
469 ExitAfterAbort = true;
470 siglongjmp(Warn_restart, 1);
477 * Serious crash time. Postmaster will observe nonzero process
478 * exit status and kill the other backends too.
480 * XXX: what if we are *in* the postmaster? proc_exit() won't kill
488 /* We reach here if lev <= NOTICE. OK to return to caller. */
491 #ifndef PG_STANDALONE
499 Err_file = Debugfile = -1;
500 ElogDebugIndentLevel = 0;
502 if (OutputFileName[0])
504 if ((fd = open(OutputFileName, O_CREAT | O_APPEND | O_WRONLY,
506 elog(FATAL, "DebugFileOpen: open of %s: %m",
512 * If the file is a tty and we're running under the postmaster,
513 * try to send stdout there as well (if it isn't a tty then stderr
514 * will block out stdout, so we may as well let stdout go wherever
515 * it was going before).
519 !freopen(OutputFileName, "a", stdout))
520 elog(FATAL, "DebugFileOpen: %s reopen as stdout: %m",
522 if (!freopen(OutputFileName, "a", stderr))
523 elog(FATAL, "DebugFileOpen: %s reopen as stderr: %m",
525 Err_file = Debugfile = fileno(stderr);
530 * If no filename was specified, send debugging output to stderr. If
531 * stderr has been hosed, try to open a file.
534 if (fcntl(fd, F_GETFD, 0) < 0)
536 snprintf(OutputFileName, MAXPGPATH, "%s%cpg.errors.%d",
537 DataDir, SEP_CHAR, (int) MyProcPid);
538 fd = open(OutputFileName, O_CREAT | O_APPEND | O_WRONLY, 0666);
541 elog(FATAL, "DebugFileOpen: could not open debugging file");
543 Err_file = Debugfile = fd;
552 * Return a timestamp string like
554 * "2000-06-04 13:12:03 "
557 print_timestamp(void)
560 static char buf[TIMESTAMP_SIZE + 1];
562 curtime = time(NULL);
564 strftime(buf, sizeof(buf),
565 "%Y-%m-%d %H:%M:%S ",
566 localtime(&curtime));
574 * Return a string like
578 * with the current pid.
583 static char buf[PID_SIZE + 1];
585 snprintf(buf, PID_SIZE + 1, "[%d] ", (int)MyProcPid);
594 * Write a message line to syslog if the syslog option is set.
596 * Our problem here is that many syslog implementations don't handle
597 * long messages in an acceptable manner. While this function doesn't
598 * help that fact, it does work around by splitting up messages into
602 write_syslog(int level, const char *line)
604 #ifndef PG_SYSLOG_LIMIT
605 # define PG_SYSLOG_LIMIT 128
608 static bool openlog_done = false;
609 static unsigned long seq = 0;
610 int len = strlen(line);
617 openlog("postgres", LOG_PID | LOG_NDELAY, LOG_LOCAL0);
622 * We add a sequence number to each log message to suppress "same"
627 /* divide into multiple syslog() calls if message is too long */
628 if (len > PG_SYSLOG_LIMIT)
630 static char buf[PG_SYSLOG_LIMIT+1];
639 strncpy(buf, line, PG_SYSLOG_LIMIT);
640 buf[PG_SYSLOG_LIMIT] = '\0';
644 /* trim to multibyte letter boundary */
645 buflen = pg_mbcliplen(buf, l, l);
649 /* already word boundary? */
650 if (isspace(line[l]) || line[l] == '\0')
654 /* try to divide in word boundary */
656 while(i > 0 && !isspace(buf[i]))
659 if (i <= 0) /* couldn't divide word boundary */
670 syslog(level, "[%lu-%d] %s", seq, chunk_nr, buf);
675 /* message short enough */
677 syslog(level, "[%lu] %s", seq, line);
680 #endif /* ENABLE_SYSLOG */