Newer
Older
/*-------------------------------------------------------------------------
*
* elog.c
Bruce Momjian
committed
* 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.92 2002/03/02 21:39:33 momjian Exp $
*
*-------------------------------------------------------------------------
*/
#include "postgres.h"
#include <time.h>
#include <fcntl.h>
#include <sys/types.h>
#include <errno.h>
#include <unistd.h>
#include <signal.h>
#include <sys/time.h>
#include <ctype.h>
#ifdef ENABLE_SYSLOG
#include <syslog.h>
#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
#define DEFAULT_SERVER_MIN_MESSAGES_STR "notice"
int server_min_messages;
char *server_min_messages_str = NULL;
const char server_min_messages_str_default[] = DEFAULT_SERVER_MIN_MESSAGES_STR;
#define DEFAULT_CLIENT_MIN_MESSAGES_STR "info"
int client_min_messages;
char *client_min_messages_str = NULL;
const char client_min_messages_str_default[] = DEFAULT_CLIENT_MIN_MESSAGES_STR;
#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 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_message_to_frontend(int type, const char *msg);
static const char *useful_strerror(int errnum);
static const char *elog_message_prefix(int lev);
#define send_notice_to_frontend(msg) send_message_to_frontend(NOTICE, msg)
#define send_error_to_frontend(msg) send_message_to_frontend(ERROR, msg)
Bruce Momjian
committed
static int Debugfile = -1;
/*--------------------
* 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.
*--------------------
Bruce Momjian
committed
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 PANIC 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;
size_t space_needed;
bool output_to_server = false;
bool output_to_client = false;
/* size of the prefix needed for timestamp and pid, if enabled */
size_t timestamp_size;
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
/* Check for old elog calls. Codes were renumbered in 7.3. 2002-02-24 */
if (lev < DEBUG5)
elog(FATAL, "Pre-7.3 object file made an elog() call. Recompile.");
if (Use_syslog <= 1 || whereToSendOutput == Debug)
{
if (lev == LOG)
{
if (server_min_messages == LOG)
output_to_server = true;
else if (server_min_messages < FATAL)
output_to_server = true;
}
/* lev != LOG */
else
{
if (server_min_messages == LOG)
{
if (lev >= FATAL)
output_to_server = true;
}
/* Neither is LOG */
else if (lev >= server_min_messages)
output_to_server = true;
}
}
if (lev >= client_min_messages && whereToSendOutput == Remote)
output_to_client = true;
/* optimization to prevent work for messages that would never be output */
if (lev < ERROR && Use_syslog < 1 &&
output_to_server == false && output_to_client == false)
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 PANIC
* errors. See miscadmin.h.
*/
if (lev == ERROR || lev == FATAL)
{
if (CritSectionCount > 0)
lev = PANIC;
prefix = elog_message_prefix(lev);
timestamp_size = 0;
if (Log_timestamp)
timestamp_size += TIMESTAMP_SIZE;
if (Log_pid)
timestamp_size += PID_SIZE;
* 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)
{
/*
* Prints the failure line of the COPY. Wow, what a hack! bjm
* Translators: Error message 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 != PANIC)
{
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 == PANIC)
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.
bp += strlen(bp);
break;
}
{
/* copy % and next char --- this avoids trouble with %%m */
*bp++ = *cp++;
*bp++ = *cp;
}
}
else
*bp++ = *cp;
* 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 (;;)
{
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 */
if (lev != FATAL && lev != PANIC)
{
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)
switch (lev)
{
case DEBUG1:
case DEBUG2:
case DEBUG3:
case DEBUG4:
case DEBUG5:
syslog_level = LOG_DEBUG;
break;
case LOG:
case INFO:
syslog_level = LOG_INFO;
break;
case NOTICE:
syslog_level = LOG_NOTICE;
break;
case ERROR:
syslog_level = LOG_WARNING;
break;
case FATAL:
syslog_level = LOG_ERR;
break;
case PANIC:
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 server logs or server terminal */
if (output_to_server)
Peter Eisentraut
committed
write(2, msg_buf, strlen(msg_buf));
/* Should we output to the client too? */
if (output_to_client)
/* 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);
/*
* 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);
/* 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(PANIC, "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 == PANIC)
* 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. */
DebugFileOpen(void)
Bruce Momjian
committed
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);
}
/*
* 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 a timestamp string like
*
*/
static const char *
print_timestamp(void)
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
*
*
* 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
#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 unsigned long seq = 0;
static int syslog_fac = LOG_LOCAL0;
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;
Peter Eisentraut
committed
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)
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)
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 */
while (i > 0 && !isspace((unsigned char) buf[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_message_to_frontend(int type, const char *msg)
{
StringInfoData buf;
AssertArg(type <= ERROR);
pq_beginmessage(&buf);
pq_sendbyte(&buf, type != ERROR ? 'N' : 'E'); /* N is INFO or NOTICE */
pq_sendstring(&buf, msg);
pq_endmessage(&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;
Peter Eisentraut
committed
if (errnum == ERANGE)
/* small trick to save creating many regression test result files */
str = gettext("Numerical result out of range");
else
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 DEBUG1:
case DEBUG2:
case DEBUG3:
case DEBUG4:
case DEBUG5:
prefix = gettext("DEBUG: ");
break;
case LOG:
prefix = gettext("LOG: ");
break;
case INFO:
prefix = gettext("INFO: ");
break;
case NOTICE:
prefix = gettext("NOTICE: ");
break;
case ERROR:
prefix = gettext("ERROR: ");
break;
case FATAL:
prefix = gettext("FATAL: ");
break;
case PANIC:
prefix = gettext("PANIC: ");
break;
}
Assert(prefix != NULL);
return prefix;
}
823
824
825
826
827
828
829
830
831
832
833
834
835
836
837
838
839
840
841
842
843
844
845
846
847
848
849
850
851
852
853
854
855
856
857
858
859
860
861
862
863
864
865
866
867
868
869
870
871
872
873
874
875
876
877
878
879
880
881
882
883
884
885
886
887
888
889
890
891
892
893
894
895
896
897
898
899
900
901
902
903
904
905
906
907
908
909
910
911
912
913
914
915
916
917
918
919
920
921
/*
* GUC support routines
*/
bool
check_server_min_messages(const char *lev)
{
if (strcasecmp(lev, "debug") == 0 ||
strcasecmp(lev, "debug1") == 0 ||
strcasecmp(lev, "debug2") == 0 ||
strcasecmp(lev, "debub3") == 0 ||
strcasecmp(lev, "debug4") == 0 ||
strcasecmp(lev, "debug5") == 0 ||
strcasecmp(lev, "log") == 0 ||
strcasecmp(lev, "info") == 0 ||
strcasecmp(lev, "notice") == 0 ||
strcasecmp(lev, "error") == 0 ||
strcasecmp(lev, "fatal") == 0 ||
strcasecmp(lev, "panic") == 0)
return true;
return false;
}
void
assign_server_min_messages(const char *lev)
{
if (strcasecmp(lev, "debug1") == 0)
server_min_messages = DEBUG1;
else if (strcasecmp(lev, "debug2") == 0)
server_min_messages = DEBUG2;
else if (strcasecmp(lev, "debug3") == 0)
server_min_messages = DEBUG3;
else if (strcasecmp(lev, "debug4") == 0)
server_min_messages = DEBUG4;
else if (strcasecmp(lev, "debug5") == 0)
server_min_messages = DEBUG5;
else if (strcasecmp(lev, "log") == 0)
server_min_messages = LOG;
else if (strcasecmp(lev, "info") == 0)
server_min_messages = INFO;
else if (strcasecmp(lev, "notice") == 0)
server_min_messages = NOTICE;
else if (strcasecmp(lev, "error") == 0)
server_min_messages = ERROR;
else if (strcasecmp(lev, "fatal") == 0)
server_min_messages = FATAL;
else if (strcasecmp(lev, "panic") == 0)
server_min_messages = PANIC;
else
/* Can't get here unless guc.c screwed up */
elog(ERROR, "bogus server_min_messages %s", lev);
}
bool
check_client_min_messages(const char *lev)
{
if (strcasecmp(lev, "debug") == 0 ||
strcasecmp(lev, "debug1") == 0 ||
strcasecmp(lev, "debug2") == 0 ||
strcasecmp(lev, "debug3") == 0 ||
strcasecmp(lev, "debug4") == 0 ||
strcasecmp(lev, "debug5") == 0 ||
strcasecmp(lev, "log") == 0 ||
strcasecmp(lev, "info") == 0 ||
strcasecmp(lev, "notice") == 0 ||
strcasecmp(lev, "error") == 0)
return true;
return false;
}
void
assign_client_min_messages(const char *lev)
{
if (strcasecmp(lev, "debug1") == 0)
client_min_messages = DEBUG1;
else if (strcasecmp(lev, "debug2") == 0)
client_min_messages = DEBUG2;
else if (strcasecmp(lev, "debug3") == 0)
client_min_messages = DEBUG3;
else if (strcasecmp(lev, "debug4") == 0)
client_min_messages = DEBUG4;
else if (strcasecmp(lev, "debug5") == 0)
client_min_messages = DEBUG5;
else if (strcasecmp(lev, "log") == 0)
client_min_messages = LOG;
else if (strcasecmp(lev, "info") == 0)
client_min_messages = INFO;
else if (strcasecmp(lev, "notice") == 0)
client_min_messages = NOTICE;
else if (strcasecmp(lev, "error") == 0)
client_min_messages = ERROR;
else
/* Can't get here unless guc.c screwed up */
elog(ERROR, "bogus client_min_messages %s", lev);
}