/*------------------------------------------------------------------------- * * elog.c * error logger * * Portions Copyright (c) 1996-2001, PostgreSQL Global Development Group * Portions Copyright (c) 1994, Regents of the University of California * * * IDENTIFICATION * $Header: /cvsroot/pgsql/src/backend/utils/error/elog.c,v 1.86 2001/06/08 21:16:48 petere Exp $ * *------------------------------------------------------------------------- */ #include "postgres.h" #include #include #include #include #include #include #include #include #ifdef ENABLE_SYSLOG #include #endif #include "commands/copy.h" #include "libpq/libpq.h" #include "libpq/pqformat.h" #include "miscadmin.h" #include "storage/proc.h" #include "tcop/tcopprot.h" #include "utils/memutils.h" #ifdef MULTIBYTE #include "mb/pg_wchar.h" #endif #ifdef ENABLE_SYSLOG /* * 0 = only stdout/stderr * 1 = stdout+stderr and syslog * 2 = syslog only * ... in theory anyway */ int Use_syslog = 0; char *Syslog_facility; char *Syslog_ident; static void write_syslog(int level, const char *line); #else #define Use_syslog 0 #endif bool Log_timestamp; bool Log_pid; #define TIMESTAMP_SIZE 20 /* format `YYYY-MM-DD HH:MM:SS ' */ #define PID_SIZE 9 /* format `[123456] ' */ static const char *print_timestamp(void); static const char *print_pid(void); static void send_notice_to_frontend(const char *msg); static void send_error_to_frontend(const char *msg); static const char *useful_strerror(int errnum); static const char *elog_message_prefix(int lev); static int Debugfile = -1; /*-------------------- * elog * Primary error logging function. * * 'lev': error level; indicates recovery action to take, if any. * 'fmt': a printf-style string. * Additional arguments, if any, are formatted per %-escapes in 'fmt'. * * In addition to the usual %-escapes recognized by printf, "%m" in * fmt is replaced by the error message for the current value of errno. * * Note: no newline is needed at the end of the fmt string, since * elog will provide one for the output methods that need it. * * If 'lev' is ERROR or worse, control does not return to the caller. * See elog.h for the error level definitions. *-------------------- */ void elog(int lev, const char *fmt,...) { va_list ap; /* * The expanded format and final output message are dynamically * allocated if necessary, but not if they fit in the "reasonable * size" buffers shown here. In extremis, we'd rather depend on * having a few hundred bytes of stack space than on malloc() still * working (since memory-clobber errors often take out malloc first). * Don't make these buffers unreasonably large though, on pain of * having to chase a bug with no error message. * * Note that we use malloc() not palloc() because we want to retain * control if we run out of memory. palloc() would recursively call * elog(ERROR), which would be all right except if we are working on a * FATAL or REALLYFATAL error. We'd lose track of the fatal condition * and report a mere ERROR to outer loop, which would be a Bad Thing. * So, we substitute an appropriate message in-place, without * downgrading the level if it's above ERROR. */ char fmt_fixedbuf[128]; char msg_fixedbuf[256]; char *fmt_buf = fmt_fixedbuf; char *msg_buf = msg_fixedbuf; /* for COPY line numbers */ char copylineno_buf[32]; const char *errorstr; const char *prefix; const char *cp; char *bp; size_t space_needed; /* size of the prefix needed for timestamp and pid, if enabled */ size_t timestamp_size; /* ignore debug msgs if noplace to send */ if (lev == DEBUG && Debugfile < 0) return; /* Save error str before calling any function that might change errno */ errorstr = useful_strerror(errno); /* * Convert initialization errors into fatal errors. This is * probably redundant, because Warn_restart_ready won't be set * anyway. */ if (lev == ERROR && IsInitProcessingMode()) lev = FATAL; /* * If we are inside a critical section, all errors become * REALLYFATAL errors. See miscadmin.h. */ if (lev == ERROR || lev == FATAL) { if (CritSectionCount > 0) lev = REALLYFATAL; } prefix = elog_message_prefix(lev); timestamp_size = 0; if (Log_timestamp) timestamp_size += TIMESTAMP_SIZE; if (Log_pid) timestamp_size += PID_SIZE; fmt = gettext(fmt); /* * Set up the expanded format, consisting of the prefix string plus * input format, with any %m replaced by strerror() string (since * vsnprintf won't know what to do with %m). To keep space * calculation simple, we only allow one %m. */ space_needed = timestamp_size + strlen(prefix) + strlen(fmt) + strlen(errorstr) + 1; if (copy_lineno) { /* translator: This string will be truncated at 31 characters. */ snprintf(copylineno_buf, 32, gettext("copy: line %d, "), copy_lineno); space_needed += strlen(copylineno_buf); } if (space_needed > sizeof(fmt_fixedbuf)) { fmt_buf = malloc(space_needed); if (fmt_buf == NULL) { /* We're up against it, convert to out-of-memory error */ fmt_buf = fmt_fixedbuf; if (lev != FATAL && lev != REALLYFATAL) { lev = ERROR; prefix = elog_message_prefix(lev); } /* * gettext doesn't allocate memory, except in the very * first call (which this isn't), so it's safe to * translate here. Worst case we get the untranslated * string back. */ /* translator: This must fit in fmt_fixedbuf. */ fmt = gettext("elog: out of memory"); } } fmt_buf[0] = '\0'; if (Log_timestamp) strcat(fmt_buf, print_timestamp()); if (Log_pid) strcat(fmt_buf, print_pid()); strcat(fmt_buf, prefix); /* If error was in CopyFrom() print the offending line number -- dz */ if (copy_lineno) { strcat(fmt_buf, copylineno_buf); if (lev == ERROR || lev == FATAL || lev == REALLYFATAL) copy_lineno = 0; } bp = fmt_buf + strlen(fmt_buf); for (cp = fmt; *cp; cp++) { if (cp[0] == '%' && cp[1] != '\0') { if (cp[1] == 'm') { /* * XXX If there are any %'s in errorstr then vsnprintf * will do the Wrong Thing; do we need to cope? Seems * unlikely that % would appear in system errors. */ strcpy(bp, errorstr); /* * copy the rest of fmt literally, since we can't afford * to insert another %m. */ strcat(bp, cp + 2); bp += strlen(bp); break; } else { /* copy % and next char --- this avoids trouble with %%m */ *bp++ = *cp++; *bp++ = *cp; } } else *bp++ = *cp; } *bp = '\0'; /* * Now generate the actual output text using vsnprintf(). Be sure to * leave space for \n added later as well as trailing null. */ space_needed = sizeof(msg_fixedbuf); for (;;) { int nprinted; va_start(ap, fmt); nprinted = vsnprintf(msg_buf, space_needed - 2, fmt_buf, ap); va_end(ap); /* * Note: some versions of vsnprintf return the number of chars * actually stored, but at least one returns -1 on failure. Be * conservative about believing whether the print worked. */ if (nprinted >= 0 && nprinted < space_needed - 3) break; /* It didn't work, try to get a bigger buffer */ if (msg_buf != msg_fixedbuf) free(msg_buf); space_needed *= 2; msg_buf = malloc(space_needed); if (msg_buf == NULL) { /* We're up against it, convert to out-of-memory error */ msg_buf = msg_fixedbuf; if (lev != FATAL && lev != REALLYFATAL) { lev = ERROR; prefix = elog_message_prefix(lev); } msg_buf[0] = '\0'; if (Log_timestamp) strcat(msg_buf, print_timestamp()); if (Log_pid) strcat(msg_buf, print_pid()); strcat(msg_buf, prefix); strcat(msg_buf, gettext("elog: out of memory")); break; } } /* * Message prepared; send it where it should go */ #ifdef ENABLE_SYSLOG /* Write to syslog, if enabled */ if (Use_syslog >= 1) { int syslog_level; switch (lev) { case DEBUG: syslog_level = LOG_DEBUG; break; case NOTICE: syslog_level = LOG_NOTICE; break; case ERROR: syslog_level = LOG_WARNING; break; case FATAL: syslog_level = LOG_ERR; break; case REALLYFATAL: default: syslog_level = LOG_CRIT; break; } write_syslog(syslog_level, msg_buf + timestamp_size); } #endif /* ENABLE_SYSLOG */ /* syslog doesn't want a trailing newline, but other destinations do */ strcat(msg_buf, "\n"); /* Write to debug file, if open and enabled */ /* NOTE: debug file is typically pointed at stderr */ if (Debugfile >= 0 && Use_syslog <= 1) write(Debugfile, msg_buf, strlen(msg_buf)); if (lev > DEBUG && whereToSendOutput == Remote) { /* Send IPC message to the front-end program */ MemoryContext oldcxt; /* * Since backend libpq may call palloc(), switch to a context * where there's fairly likely to be some free space. After all * the pushups above, we don't want to drop the ball by running * out of space now... */ oldcxt = MemoryContextSwitchTo(ErrorContext); if (lev == NOTICE) /* exclude the timestamp from msg sent to frontend */ send_notice_to_frontend(msg_buf + timestamp_size); else { /* * Abort any COPY OUT in progress when an error is detected. * This hack is necessary because of poor design of copy * protocol. */ pq_endcopyout(true); send_error_to_frontend(msg_buf + timestamp_size); } MemoryContextSwitchTo(oldcxt); } if (lev > DEBUG && whereToSendOutput != Remote) { /* * We are running as an interactive backend, so just send the * message to stderr. But don't send a duplicate if Debugfile * write, above, already sent to stderr. */ if (Debugfile != fileno(stderr)) fputs(msg_buf, stderr); } /* done with the message, release space */ if (fmt_buf != fmt_fixedbuf) free(fmt_buf); if (msg_buf != msg_fixedbuf) free(msg_buf); /* * Perform error recovery action as specified by lev. */ if (lev == ERROR || lev == FATAL) { /* Prevent immediate interrupt while entering error recovery */ ImmediateInterruptOK = false; /* * For a FATAL error, we let proc_exit clean up and exit. * * If we have not yet entered the main backend loop (ie, we are in * the postmaster or in backend startup), we also go directly to * proc_exit. The same is true if anyone tries to report an error * after proc_exit has begun to run. (It's proc_exit's * responsibility to see that this doesn't turn into infinite * recursion!) But in the latter case, we exit with nonzero exit * code to indicate that something's pretty wrong. We also want * to exit with nonzero exit code if not running under the * postmaster (for example, if we are being run from the initdb * script, we'd better return an error status). */ if (lev == FATAL || !Warn_restart_ready || proc_exit_inprogress) { /* * fflush here is just to improve the odds that we get to see * the error message, in case things are so hosed that * proc_exit crashes. Any other code you might be tempted to * add here should probably be in an on_proc_exit callback * instead. */ fflush(stdout); fflush(stderr); proc_exit(proc_exit_inprogress || !IsUnderPostmaster); } /* * Guard against infinite loop from elog() during error recovery. */ if (InError) elog(REALLYFATAL, "elog: error during error recovery, giving up!"); InError = true; /* * Otherwise we can return to the main loop in postgres.c. */ siglongjmp(Warn_restart, 1); } if (lev == FATAL || lev == REALLYFATAL) { /* * Serious crash time. Postmaster will observe nonzero process * exit status and kill the other backends too. * * XXX: what if we are *in* the postmaster? proc_exit() won't kill * our children... */ ImmediateInterruptOK = false; fflush(stdout); fflush(stderr); proc_exit(lev); } /* We reach here if lev <= NOTICE. OK to return to caller. */ } int DebugFileOpen(void) { int fd, istty; Debugfile = -1; if (OutputFileName[0]) { /* * A debug-output file name was given. * * Make sure we can write the file, and find out if it's a tty. */ if ((fd = open(OutputFileName, O_CREAT | O_APPEND | O_WRONLY, 0666)) < 0) elog(FATAL, "DebugFileOpen: open of %s: %m", OutputFileName); istty = isatty(fd); close(fd); /* * Redirect our stderr to the debug output file. */ if (!freopen(OutputFileName, "a", stderr)) elog(FATAL, "DebugFileOpen: %s reopen as stderr: %m", OutputFileName); Debugfile = fileno(stderr); /* * If the file is a tty and we're running under the postmaster, * try to send stdout there as well (if it isn't a tty then stderr * will block out stdout, so we may as well let stdout go wherever * it was going before). */ if (istty && IsUnderPostmaster) if (!freopen(OutputFileName, "a", stdout)) elog(FATAL, "DebugFileOpen: %s reopen as stdout: %m", OutputFileName); return Debugfile; } /* * If no filename was specified, send debugging output to stderr. If * stderr has been hosed, try to open a file. */ fd = fileno(stderr); if (fcntl(fd, F_GETFD, 0) < 0) { snprintf(OutputFileName, MAXPGPATH, "%s/pg.errors.%d", DataDir, (int) MyProcPid); fd = open(OutputFileName, O_CREAT | O_APPEND | O_WRONLY, 0666); } if (fd < 0) elog(FATAL, "DebugFileOpen: could not open debugging file"); Debugfile = fd; return Debugfile; } /* * Return a timestamp string like * * "2000-06-04 13:12:03 " */ static const char * print_timestamp(void) { time_t curtime; static char buf[TIMESTAMP_SIZE + 1]; curtime = time(NULL); strftime(buf, sizeof(buf), "%Y-%m-%d %H:%M:%S ", localtime(&curtime)); return buf; } /* * Return a string like * * "[123456] " * * with the current pid. */ static const char * print_pid(void) { static char buf[PID_SIZE + 1]; snprintf(buf, PID_SIZE + 1, "[%d] ", (int) MyProcPid); return buf; } #ifdef ENABLE_SYSLOG #ifndef PG_SYSLOG_LIMIT #define PG_SYSLOG_LIMIT 128 #endif /* * Write a message line to syslog if the syslog option is set. * * Our problem here is that many syslog implementations don't handle * long messages in an acceptable manner. While this function doesn't * help that fact, it does work around by splitting up messages into * smaller pieces. */ static void write_syslog(int level, const char *line) { static bool openlog_done = false; static unsigned long seq = 0; static int syslog_fac = LOG_LOCAL0; int len = strlen(line); if (Use_syslog == 0) return; if (!openlog_done) { if (strcasecmp(Syslog_facility, "LOCAL0") == 0) syslog_fac = LOG_LOCAL0; if (strcasecmp(Syslog_facility, "LOCAL1") == 0) syslog_fac = LOG_LOCAL1; if (strcasecmp(Syslog_facility, "LOCAL2") == 0) syslog_fac = LOG_LOCAL2; if (strcasecmp(Syslog_facility, "LOCAL3") == 0) syslog_fac = LOG_LOCAL3; if (strcasecmp(Syslog_facility, "LOCAL4") == 0) syslog_fac = LOG_LOCAL4; if (strcasecmp(Syslog_facility, "LOCAL5") == 0) syslog_fac = LOG_LOCAL5; if (strcasecmp(Syslog_facility, "LOCAL6") == 0) syslog_fac = LOG_LOCAL6; if (strcasecmp(Syslog_facility, "LOCAL7") == 0) syslog_fac = LOG_LOCAL7; openlog(Syslog_ident, LOG_PID | LOG_NDELAY, syslog_fac); openlog_done = true; } /* * We add a sequence number to each log message to suppress "same" * messages. */ seq++; /* divide into multiple syslog() calls if message is too long */ /* or if the message contains embedded NewLine(s) '\n' */ if (len > PG_SYSLOG_LIMIT || strchr(line, '\n') != NULL) { int chunk_nr = 0; while (len > 0) { char buf[PG_SYSLOG_LIMIT + 1]; int buflen; int l; int i; /* if we start at a newline, move ahead one char */ if (line[0] == '\n') { line++; len--; continue; } strncpy(buf, line, PG_SYSLOG_LIMIT); buf[PG_SYSLOG_LIMIT] = '\0'; if (strchr(buf, '\n') != NULL) *strchr(buf, '\n') = '\0'; l = strlen(buf); #ifdef MULTIBYTE /* trim to multibyte letter boundary */ buflen = pg_mbcliplen(buf, l, l); if (buflen <= 0) return; buf[buflen] = '\0'; l = strlen(buf); #endif /* already word boundary? */ if (isspace((unsigned char) line[l]) || line[l] == '\0') buflen = l; else { /* try to divide at word boundary */ i = l - 1; while (i > 0 && !isspace((unsigned char) buf[i])) i--; if (i <= 0) /* couldn't divide word boundary */ buflen = l; else { buflen = i; buf[i] = '\0'; } } chunk_nr++; syslog(level, "[%lu-%d] %s", seq, chunk_nr, buf); line += buflen; len -= buflen; } } else { /* message short enough */ syslog(level, "[%lu] %s", seq, line); } } #endif /* ENABLE_SYSLOG */ static void send_notice_or_error_to_frontend(int type, const char *msg); static void send_notice_to_frontend(const char *msg) { send_notice_or_error_to_frontend(NOTICE, msg); } static void send_error_to_frontend(const char *msg) { send_notice_or_error_to_frontend(ERROR, msg); } static void send_notice_or_error_to_frontend(int type, const char *msg) { StringInfo buf; AssertArg(type == NOTICE || type == ERROR); buf = makeStringInfo(); pq_beginmessage(buf); pq_sendbyte(buf, type == NOTICE ? 'N' : 'E'); pq_sendstring(buf, msg); pq_endmessage(buf); pfree(buf); /* * This flush is normally not necessary, since postgres.c will * flush out waiting data when control returns to the main loop. * But it seems best to leave it here, so that the client has some * clue what happened if the backend dies before getting back to * the main loop ... error/notice messages should not be a * performance-critical path anyway, so an extra flush won't hurt * much ... */ pq_flush(); } static const char *useful_strerror(int errnum) { /* this buffer is only used if errno has a bogus value */ static char errorstr_buf[48]; char *str; str = strerror(errnum); /* * Some strerror()s return an empty string for out-of-range errno. * This is ANSI C spec compliant, but not exactly useful. */ if (str == NULL || *str == '\0') { /* translator: This string will be truncated at 47 characters expanded. */ snprintf(errorstr_buf, 48, gettext("operating system error %d"), errnum); str = errorstr_buf; } return str; } static const char * elog_message_prefix(int lev) { const char * prefix = NULL; switch (lev) { case DEBUG: prefix = gettext("DEBUG: "); break; case NOTICE: prefix = gettext("NOTICE: "); break; case ERROR: prefix = gettext("ERROR: "); break; case FATAL: prefix = gettext("FATAL 1: "); break; case REALLYFATAL: prefix = gettext("FATAL 2: "); break; } Assert(prefix != NULL); return prefix; }