1 /*-------------------------------------------------------------------------
6 * Portions Copyright (c) 1996-2001, PostgreSQL Global Development Group
7 * Portions Copyright (c) 1994, Regents of the University of California
11 * $Header: /cvsroot/pgsql/src/backend/utils/error/elog.c,v 1.95 2002/04/04 04:43:44 momjian Exp $
13 *-------------------------------------------------------------------------
19 #include <sys/types.h>
29 #include "commands/copy.h"
30 #include "libpq/libpq.h"
31 #include "libpq/pqformat.h"
32 #include "miscadmin.h"
33 #include "storage/proc.h"
34 #include "tcop/tcopprot.h"
35 #include "utils/memutils.h"
38 #include "mb/pg_wchar.h"
41 int server_min_messages;
42 char *server_min_messages_str = NULL;
43 const char server_min_messages_str_default[] = "notice";
45 int client_min_messages;
46 char *client_min_messages_str = NULL;
47 const char client_min_messages_str_default[] = "notice";
51 * 0 = only stdout/stderr
52 * 1 = stdout+stderr and syslog
54 * ... in theory anyway
57 char *Syslog_facility;
60 static void write_syslog(int level, const char *line);
69 #define TIMESTAMP_SIZE 20 /* format `YYYY-MM-DD HH:MM:SS ' */
70 #define PID_SIZE 9 /* format `[123456] ' */
72 static const char *print_timestamp(void);
73 static const char *print_pid(void);
74 static void send_message_to_frontend(int type, const char *msg);
75 static const char *useful_strerror(int errnum);
76 static const char *elog_message_prefix(int lev);
78 static int Debugfile = -1;
81 /*--------------------
83 * Primary error logging function.
85 * 'lev': error level; indicates recovery action to take, if any.
86 * 'fmt': a printf-style string.
87 * Additional arguments, if any, are formatted per %-escapes in 'fmt'.
89 * In addition to the usual %-escapes recognized by printf, "%m" in
90 * fmt is replaced by the error message for the current value of errno.
92 * Note: no newline is needed at the end of the fmt string, since
93 * elog will provide one for the output methods that need it.
95 * If 'lev' is ERROR or worse, control does not return to the caller.
96 * See elog.h for the error level definitions.
100 elog(int lev, const char *fmt,...)
104 * The expanded format and final output message are dynamically
105 * allocated if necessary, but not if they fit in the "reasonable
106 * size" buffers shown here. In extremis, we'd rather depend on
107 * having a few hundred bytes of stack space than on malloc() still
108 * working (since memory-clobber errors often take out malloc first).
109 * Don't make these buffers unreasonably large though, on pain of
110 * having to chase a bug with no error message.
112 * Note that we use malloc() not palloc() because we want to retain
113 * control if we run out of memory. palloc() would recursively call
114 * elog(ERROR), which would be all right except if we are working on a
115 * FATAL or PANIC error. We'd lose track of the fatal condition
116 * and report a mere ERROR to outer loop, which would be a Bad Thing.
117 * So, we substitute an appropriate message in-place, without
118 * downgrading the level if it's above ERROR.
120 char fmt_fixedbuf[128];
121 char msg_fixedbuf[256];
122 char *fmt_buf = fmt_fixedbuf;
123 char *msg_buf = msg_fixedbuf;
124 char copylineno_buf[32]; /* for COPY line numbers */
125 const char *errorstr;
130 size_t timestamp_size; /* prefix len for timestamp+pid */
131 bool output_to_server = false;
132 bool output_to_client = false;
134 /* Check for old elog calls. Codes were renumbered in 7.3. 2002-02-24 */
136 elog(FATAL, "Pre-7.3 object file made an elog() call. Recompile.");
139 * Convert initialization errors into fatal errors. This is probably
140 * redundant, because Warn_restart_ready won't be set anyway.
142 if (lev == ERROR && IsInitProcessingMode())
146 * If we are inside a critical section, all errors become PANIC
147 * errors. See miscadmin.h.
151 if (CritSectionCount > 0)
155 /* Determine whether message is enabled for server log output */
156 /* Complicated because LOG is sorted out-of-order for this purpose */
157 if (lev == LOG || lev == COMMERROR)
159 if (server_min_messages == LOG)
160 output_to_server = true;
161 else if (server_min_messages < FATAL)
162 output_to_server = true;
167 if (server_min_messages == LOG)
170 output_to_server = true;
173 else if (lev >= server_min_messages)
174 output_to_server = true;
177 /* Determine whether message is enabled for client output */
178 if (whereToSendOutput == Remote && lev != COMMERROR)
181 * client_min_messages is honored only after we complete the
182 * authentication handshake. This is required both for security
183 * reasons and because many clients can't handle NOTICE messages
184 * during authentication.
186 if (ClientAuthInProgress)
187 output_to_client = (lev >= ERROR);
189 output_to_client = (lev >= client_min_messages || lev == INFO);
192 /* Skip formatting effort if non-error message will not be output */
193 if (lev < ERROR && !output_to_server && !output_to_client)
196 /* Save error str before calling any function that might change errno */
197 errorstr = useful_strerror(errno);
199 /* Internationalize the error format string */
202 /* Begin formatting by determining prefix information */
203 prefix = elog_message_prefix(lev);
207 timestamp_size += TIMESTAMP_SIZE;
209 timestamp_size += PID_SIZE;
212 * Set up the expanded format, consisting of the prefix string plus
213 * input format, with any %m replaced by strerror() string (since
214 * vsnprintf won't know what to do with %m). To keep space
215 * calculation simple, we only allow one %m.
217 space_needed = timestamp_size + strlen(prefix) +
218 strlen(fmt) + strlen(errorstr) + 1;
223 * Prints the failure line of the COPY. Wow, what a hack! bjm
224 * Translator: Error message will be truncated at 31 characters.
226 snprintf(copylineno_buf, 32, gettext("copy: line %d, "), copy_lineno);
227 space_needed += strlen(copylineno_buf);
230 if (space_needed > sizeof(fmt_fixedbuf))
232 fmt_buf = malloc(space_needed);
235 /* We're up against it, convert to out-of-memory error */
236 fmt_buf = fmt_fixedbuf;
240 prefix = elog_message_prefix(lev);
244 * gettext doesn't allocate memory, except in the very first
245 * call (which this isn't), so it's safe to translate here.
246 * Worst case we get the untranslated string back.
248 /* translator: This must fit in fmt_fixedbuf. */
249 fmt = gettext("elog: out of memory");
256 strcat(fmt_buf, print_timestamp());
258 strcat(fmt_buf, print_pid());
260 strcat(fmt_buf, prefix);
262 /* If error was in CopyFrom() print the offending line number -- dz */
265 strcat(fmt_buf, copylineno_buf);
270 bp = fmt_buf + strlen(fmt_buf);
272 for (cp = fmt; *cp; cp++)
274 if (cp[0] == '%' && cp[1] != '\0')
279 * XXX If there are any %'s in errorstr then vsnprintf
280 * will do the Wrong Thing; do we need to cope? Seems
281 * unlikely that % would appear in system errors.
283 strcpy(bp, errorstr);
286 * copy the rest of fmt literally, since we can't afford
287 * to insert another %m.
295 /* copy % and next char --- this avoids trouble with %%m */
306 * Now generate the actual output text using vsnprintf(). Be sure to
307 * leave space for \n added later as well as trailing null.
309 space_needed = sizeof(msg_fixedbuf);
315 nprinted = vsnprintf(msg_buf, space_needed - 2, fmt_buf, ap);
319 * Note: some versions of vsnprintf return the number of chars
320 * actually stored, but at least one returns -1 on failure. Be
321 * conservative about believing whether the print worked.
323 if (nprinted >= 0 && nprinted < space_needed - 3)
325 /* It didn't work, try to get a bigger buffer */
326 if (msg_buf != msg_fixedbuf)
329 msg_buf = malloc(space_needed);
332 /* We're up against it, convert to out-of-memory error */
333 msg_buf = msg_fixedbuf;
337 prefix = elog_message_prefix(lev);
341 strcat(msg_buf, print_timestamp());
343 strcat(msg_buf, print_pid());
344 strcat(msg_buf, prefix);
345 strcat(msg_buf, gettext("elog: out of memory"));
351 * Message prepared; send it where it should go
355 /* Write to syslog, if enabled */
356 if (output_to_server && Use_syslog >= 1)
367 syslog_level = LOG_DEBUG;
372 syslog_level = LOG_INFO;
376 syslog_level = LOG_NOTICE;
379 syslog_level = LOG_WARNING;
382 syslog_level = LOG_ERR;
386 syslog_level = LOG_CRIT;
390 write_syslog(syslog_level, msg_buf + timestamp_size);
392 #endif /* ENABLE_SYSLOG */
394 /* syslog doesn't want a trailing newline, but other destinations do */
395 strcat(msg_buf, "\n");
397 /* Write to stderr, if enabled */
398 if (output_to_server && (Use_syslog <= 1 || whereToSendOutput == Debug))
399 write(2, msg_buf, strlen(msg_buf));
401 /* Send to client, if enabled */
402 if (output_to_client)
404 /* Send IPC message to the front-end program */
405 MemoryContext oldcxt;
408 * Since backend libpq may call palloc(), switch to a context
409 * where there's fairly likely to be some free space. After all
410 * the pushups above, we don't want to drop the ball by running
411 * out of space now...
413 oldcxt = MemoryContextSwitchTo(ErrorContext);
416 /* exclude the timestamp from msg sent to frontend */
417 send_message_to_frontend(lev, msg_buf + timestamp_size);
421 * Abort any COPY OUT in progress when an error is detected.
422 * This hack is necessary because of poor design of copy
426 send_message_to_frontend(ERROR, msg_buf + timestamp_size);
429 MemoryContextSwitchTo(oldcxt);
432 /* done with the message, release space */
433 if (fmt_buf != fmt_fixedbuf)
435 if (msg_buf != msg_fixedbuf)
439 * Perform error recovery action as specified by lev.
441 if (lev == ERROR || lev == FATAL)
443 /* Prevent immediate interrupt while entering error recovery */
444 ImmediateInterruptOK = false;
447 * If we just reported a startup failure, the client will
448 * disconnect on receiving it, so don't send any more to the client.
450 if (!Warn_restart_ready && whereToSendOutput == Remote)
451 whereToSendOutput = None;
454 * For a FATAL error, we let proc_exit clean up and exit.
456 * If we have not yet entered the main backend loop (ie, we are in
457 * the postmaster or in backend startup), we also go directly to
458 * proc_exit. The same is true if anyone tries to report an error
459 * after proc_exit has begun to run. (It's proc_exit's
460 * responsibility to see that this doesn't turn into infinite
461 * recursion!) But in the latter case, we exit with nonzero exit
462 * code to indicate that something's pretty wrong. We also want
463 * to exit with nonzero exit code if not running under the
464 * postmaster (for example, if we are being run from the initdb
465 * script, we'd better return an error status).
467 if (lev == FATAL || !Warn_restart_ready || proc_exit_inprogress)
470 * fflush here is just to improve the odds that we get to see
471 * the error message, in case things are so hosed that
472 * proc_exit crashes. Any other code you might be tempted to
473 * add here should probably be in an on_proc_exit callback
478 proc_exit(proc_exit_inprogress || !IsUnderPostmaster);
482 * Guard against infinite loop from elog() during error recovery.
485 elog(PANIC, "elog: error during error recovery, giving up!");
489 * Otherwise we can return to the main loop in postgres.c.
491 siglongjmp(Warn_restart, 1);
497 * Serious crash time. Postmaster will observe nonzero process
498 * exit status and kill the other backends too.
500 * XXX: what if we are *in* the postmaster? proc_exit() won't kill
503 ImmediateInterruptOK = false;
509 /* We reach here if lev <= WARNING. OK to return to caller. */
521 if (OutputFileName[0])
524 * A debug-output file name was given.
526 * Make sure we can write the file, and find out if it's a tty.
528 if ((fd = open(OutputFileName, O_CREAT | O_APPEND | O_WRONLY,
530 elog(FATAL, "DebugFileOpen: open of %s: %m",
536 * Redirect our stderr to the debug output file.
538 if (!freopen(OutputFileName, "a", stderr))
539 elog(FATAL, "DebugFileOpen: %s reopen as stderr: %m",
541 Debugfile = fileno(stderr);
544 * If the file is a tty and we're running under the postmaster,
545 * try to send stdout there as well (if it isn't a tty then stderr
546 * will block out stdout, so we may as well let stdout go wherever
547 * it was going before).
549 if (istty && IsUnderPostmaster)
550 if (!freopen(OutputFileName, "a", stdout))
551 elog(FATAL, "DebugFileOpen: %s reopen as stdout: %m",
557 * If no filename was specified, send debugging output to stderr. If
558 * stderr has been hosed, try to open a file.
561 if (fcntl(fd, F_GETFD, 0) < 0)
563 snprintf(OutputFileName, MAXPGPATH, "%s/pg.errors.%d",
564 DataDir, (int) MyProcPid);
565 fd = open(OutputFileName, O_CREAT | O_APPEND | O_WRONLY, 0666);
568 elog(FATAL, "DebugFileOpen: could not open debugging file");
576 * Return a timestamp string like
578 * "2000-06-04 13:12:03 "
581 print_timestamp(void)
584 static char buf[TIMESTAMP_SIZE + 1];
586 curtime = time(NULL);
588 strftime(buf, sizeof(buf),
589 "%Y-%m-%d %H:%M:%S ",
590 localtime(&curtime));
598 * Return a string like
602 * with the current pid.
607 static char buf[PID_SIZE + 1];
609 snprintf(buf, PID_SIZE + 1, "[%d] ", (int) MyProcPid);
617 #ifndef PG_SYSLOG_LIMIT
618 #define PG_SYSLOG_LIMIT 128
622 * Write a message line to syslog if the syslog option is set.
624 * Our problem here is that many syslog implementations don't handle
625 * long messages in an acceptable manner. While this function doesn't
626 * help that fact, it does work around by splitting up messages into
630 write_syslog(int level, const char *line)
632 static bool openlog_done = false;
633 static unsigned long seq = 0;
634 static int syslog_fac = LOG_LOCAL0;
636 int len = strlen(line);
643 if (strcasecmp(Syslog_facility, "LOCAL0") == 0)
644 syslog_fac = LOG_LOCAL0;
645 if (strcasecmp(Syslog_facility, "LOCAL1") == 0)
646 syslog_fac = LOG_LOCAL1;
647 if (strcasecmp(Syslog_facility, "LOCAL2") == 0)
648 syslog_fac = LOG_LOCAL2;
649 if (strcasecmp(Syslog_facility, "LOCAL3") == 0)
650 syslog_fac = LOG_LOCAL3;
651 if (strcasecmp(Syslog_facility, "LOCAL4") == 0)
652 syslog_fac = LOG_LOCAL4;
653 if (strcasecmp(Syslog_facility, "LOCAL5") == 0)
654 syslog_fac = LOG_LOCAL5;
655 if (strcasecmp(Syslog_facility, "LOCAL6") == 0)
656 syslog_fac = LOG_LOCAL6;
657 if (strcasecmp(Syslog_facility, "LOCAL7") == 0)
658 syslog_fac = LOG_LOCAL7;
659 openlog(Syslog_ident, LOG_PID | LOG_NDELAY, syslog_fac);
664 * We add a sequence number to each log message to suppress "same"
669 /* divide into multiple syslog() calls if message is too long */
670 /* or if the message contains embedded NewLine(s) '\n' */
671 if (len > PG_SYSLOG_LIMIT || strchr(line, '\n') != NULL)
677 char buf[PG_SYSLOG_LIMIT + 1];
682 /* if we start at a newline, move ahead one char */
690 strncpy(buf, line, PG_SYSLOG_LIMIT);
691 buf[PG_SYSLOG_LIMIT] = '\0';
692 if (strchr(buf, '\n') != NULL)
693 *strchr(buf, '\n') = '\0';
697 /* trim to multibyte letter boundary */
698 buflen = pg_mbcliplen(buf, l, l);
704 /* already word boundary? */
705 if (isspace((unsigned char) line[l]) || line[l] == '\0')
709 /* try to divide at word boundary */
711 while (i > 0 && !isspace((unsigned char) buf[i]))
714 if (i <= 0) /* couldn't divide word boundary */
725 syslog(level, "[%lu-%d] %s", seq, chunk_nr, buf);
732 /* message short enough */
733 syslog(level, "[%lu] %s", seq, line);
736 #endif /* ENABLE_SYSLOG */
740 send_message_to_frontend(int type, const char *msg)
744 AssertArg(type <= ERROR);
746 pq_beginmessage(&buf);
747 pq_sendbyte(&buf, type != ERROR ? 'N' : 'E'); /* N is INFO, NOTICE,
749 pq_sendstring(&buf, msg);
753 * This flush is normally not necessary, since postgres.c will flush
754 * out waiting data when control returns to the main loop. But it
755 * seems best to leave it here, so that the client has some clue what
756 * happened if the backend dies before getting back to the main loop
757 * ... error/notice messages should not be a performance-critical path
758 * anyway, so an extra flush won't hurt much ...
765 useful_strerror(int errnum)
767 /* this buffer is only used if errno has a bogus value */
768 static char errorstr_buf[48];
771 if (errnum == ERANGE)
772 /* small trick to save creating many regression test result files */
773 str = gettext("Numerical result out of range");
775 str = strerror(errnum);
778 * Some strerror()s return an empty string for out-of-range errno.
779 * This is ANSI C spec compliant, but not exactly useful.
781 if (str == NULL || *str == '\0')
784 * translator: This string will be truncated at 47 characters
787 snprintf(errorstr_buf, 48, gettext("operating system error %d"),
798 elog_message_prefix(int lev)
800 const char *prefix = NULL;
809 prefix = gettext("DEBUG: ");
813 prefix = gettext("LOG: ");
816 prefix = gettext("INFO: ");
819 prefix = gettext("NOTICE: ");
822 prefix = gettext("WARNING: ");
825 prefix = gettext("ERROR: ");
828 prefix = gettext("FATAL: ");
831 prefix = gettext("PANIC: ");
835 Assert(prefix != NULL);
841 * GUC support routines
845 check_server_min_messages(const char *lev)
847 if (strcasecmp(lev, "debug") == 0 ||
848 strcasecmp(lev, "debug5") == 0 ||
849 strcasecmp(lev, "debug4") == 0 ||
850 strcasecmp(lev, "debug3") == 0 ||
851 strcasecmp(lev, "debug2") == 0 ||
852 strcasecmp(lev, "debug1") == 0 ||
853 strcasecmp(lev, "info") == 0 ||
854 strcasecmp(lev, "notice") == 0 ||
855 strcasecmp(lev, "warning") == 0 ||
856 strcasecmp(lev, "error") == 0 ||
857 strcasecmp(lev, "log") == 0 ||
858 strcasecmp(lev, "fatal") == 0 ||
859 strcasecmp(lev, "panic") == 0)
865 assign_server_min_messages(const char *lev)
867 if (strcasecmp(lev, "debug") == 0)
868 server_min_messages = DEBUG5;
869 else if (strcasecmp(lev, "debug5") == 0)
870 server_min_messages = DEBUG5;
871 else if (strcasecmp(lev, "debug4") == 0)
872 server_min_messages = DEBUG4;
873 else if (strcasecmp(lev, "debug3") == 0)
874 server_min_messages = DEBUG3;
875 else if (strcasecmp(lev, "debug2") == 0)
876 server_min_messages = DEBUG2;
877 else if (strcasecmp(lev, "debug1") == 0)
878 server_min_messages = DEBUG1;
879 else if (strcasecmp(lev, "info") == 0)
880 server_min_messages = INFO;
881 else if (strcasecmp(lev, "notice") == 0)
882 server_min_messages = NOTICE;
883 else if (strcasecmp(lev, "warning") == 0)
884 server_min_messages = WARNING;
885 else if (strcasecmp(lev, "error") == 0)
886 server_min_messages = ERROR;
887 else if (strcasecmp(lev, "log") == 0)
888 server_min_messages = LOG;
889 else if (strcasecmp(lev, "fatal") == 0)
890 server_min_messages = FATAL;
891 else if (strcasecmp(lev, "panic") == 0)
892 server_min_messages = PANIC;
894 /* Can't get here unless guc.c screwed up */
895 elog(ERROR, "bogus server_min_messages %s", lev);
899 check_client_min_messages(const char *lev)
901 if (strcasecmp(lev, "debug") == 0 ||
902 strcasecmp(lev, "debug5") == 0 ||
903 strcasecmp(lev, "debug4") == 0 ||
904 strcasecmp(lev, "debug3") == 0 ||
905 strcasecmp(lev, "debug2") == 0 ||
906 strcasecmp(lev, "debug1") == 0 ||
907 strcasecmp(lev, "log") == 0 ||
908 strcasecmp(lev, "info") == 0 ||
909 strcasecmp(lev, "notice") == 0 ||
910 strcasecmp(lev, "warning") == 0 ||
911 strcasecmp(lev, "error") == 0)
917 assign_client_min_messages(const char *lev)
919 if (strcasecmp(lev, "debug") == 0)
920 client_min_messages = DEBUG5;
921 else if (strcasecmp(lev, "debug5") == 0)
922 client_min_messages = DEBUG5;
923 else if (strcasecmp(lev, "debug4") == 0)
924 client_min_messages = DEBUG4;
925 else if (strcasecmp(lev, "debug3") == 0)
926 client_min_messages = DEBUG3;
927 else if (strcasecmp(lev, "debug2") == 0)
928 client_min_messages = DEBUG2;
929 else if (strcasecmp(lev, "debug1") == 0)
930 client_min_messages = DEBUG1;
931 else if (strcasecmp(lev, "log") == 0)
932 client_min_messages = LOG;
933 else if (strcasecmp(lev, "info") == 0)
934 client_min_messages = INFO;
935 else if (strcasecmp(lev, "notice") == 0)
936 client_min_messages = NOTICE;
937 else if (strcasecmp(lev, "warning") == 0)
938 client_min_messages = WARNING;
939 else if (strcasecmp(lev, "error") == 0)
940 client_min_messages = ERROR;
942 /* Can't get here unless guc.c screwed up */
943 elog(ERROR, "bogus client_min_messages %s", lev);