From b399805e221b5407f4f459c41661c86bb580680f Mon Sep 17 00:00:00 2001 From: Tom Lane Date: Sat, 11 Sep 1999 19:06:42 +0000 Subject: [PATCH] Eliminate elog()'s hardwired limit on length of an error message. This change seems necessary in conjunction with long queries, and it cleans up some bogosity in connection with long EXPLAIN texts anyway. Note that current libpq will accept any length error message (at least until it runs out of memory); prior versions have a limit of 8K, but will cleanly discard excess error text, so there shouldn't be any big compatibility problems with old clients. --- src/backend/commands/explain.c | 27 +-- src/backend/utils/error/elog.c | 292 ++++++++++++++++++++++++--------- src/backend/utils/misc/trace.c | 35 ++-- src/include/utils/elog.h | 36 +--- 4 files changed, 245 insertions(+), 145 deletions(-) diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 07caedde8b..3b1da18783 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -4,7 +4,7 @@ * * Copyright (c) 1994-5, Regents of the University of California * - * $Id: explain.c,v 1.46 1999/08/31 01:28:28 tgl Exp $ + * $Id: explain.c,v 1.47 1999/09/11 19:06:36 tgl Exp $ * */ @@ -28,7 +28,6 @@ typedef struct ExplainState } ExplainState; static char *Explain_PlanToString(Plan *plan, ExplainState *es); -static void printLongNotice(const char *header, const char *message); static void ExplainOneQuery(Query *query, bool verbose, CommandDest dest); /* Convert a null string pointer into "<>" */ @@ -110,7 +109,7 @@ ExplainOneQuery(Query *query, bool verbose, CommandDest dest) s = nodeToString(plan); if (s) { - printLongNotice("QUERY DUMP:\n\n", s); + elog(NOTICE, "QUERY DUMP:\n\n%s", s); pfree(s); } } @@ -120,7 +119,7 @@ ExplainOneQuery(Query *query, bool verbose, CommandDest dest) s = Explain_PlanToString(plan, es); if (s) { - printLongNotice("QUERY PLAN:\n\n", s); + elog(NOTICE, "QUERY PLAN:\n\n%s", s); pfree(s); } } @@ -332,7 +331,6 @@ explain_outNode(StringInfo str, Plan *plan, int indent, ExplainState *es) } es->rtable = saved_rtable; } - return; } static char * @@ -346,22 +344,3 @@ Explain_PlanToString(Plan *plan, ExplainState *es) explain_outNode(&str, plan, 0, es); return str.data; } - -/* - * Print a message that might exceed the size of the elog message buffer. - * This is a crock ... there shouldn't be an upper limit to what you can elog(). - */ -static void -printLongNotice(const char *header, const char *message) -{ - int len = strlen(message); - - elog(NOTICE, "%.20s%.*s", header, ELOG_MAXLEN - 64, message); - len -= ELOG_MAXLEN - 64; - while (len > 0) - { - message += ELOG_MAXLEN - 64; - elog(NOTICE, "%.*s", ELOG_MAXLEN - 64, message); - len -= ELOG_MAXLEN - 64; - } -} diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c index 0567954570..11cf762e7d 100644 --- a/src/backend/utils/error/elog.c +++ b/src/backend/utils/error/elog.c @@ -7,10 +7,13 @@ * * * IDENTIFICATION - * $Header: /cvsroot/pgsql/src/backend/utils/error/elog.c,v 1.47 1999/07/17 20:18:03 momjian Exp $ + * $Header: /cvsroot/pgsql/src/backend/utils/error/elog.c,v 1.48 1999/09/11 19:06:31 tgl Exp $ * *------------------------------------------------------------------------- */ + +#include "postgres.h" + #include #include #ifndef O_RDONLY @@ -20,8 +23,6 @@ #include #include #include - -#include "postgres.h" #ifdef USE_SYSLOG #include #endif @@ -33,6 +34,10 @@ #include "tcop/tcopprot.h" #include "utils/trace.h" +extern int errno; +extern int sys_nerr; + + #ifdef USE_SYSLOG /* * Global option to control the use of syslog(3) for logging: @@ -51,84 +56,198 @@ static int Debugfile = -1; static int Err_file = -1; static int ElogDebugIndentLevel = 0; -/* +/*-------------------- * elog - * Old error logging function. + * 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,...) +elog(int lev, const char *fmt, ...) { va_list ap; - char buf[ELOG_MAXLEN], - line[ELOG_MAXLEN]; - char *bp; + /* + * 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. + */ + char fmt_fixedbuf[128]; + char msg_fixedbuf[256]; + char *fmt_buf = fmt_fixedbuf; + char *msg_buf = msg_fixedbuf; + /* this buffer is only used if errno has a bogus value: */ + char errorstr_buf[32]; + const char *errorstr; + const char *prefix; const char *cp; - extern int errno, - sys_nerr; - + char *bp; + int indent = 0; + int space_needed; #ifdef USE_SYSLOG int log_level; - #endif - int len; - int i = 0; - va_start(ap, fmt); - if (lev == DEBUG && Debugfile < 0) - return; + if (lev <= DEBUG && Debugfile < 0) + return; /* ignore debug msgs if noplace to send */ + + /* choose message prefix and indent level */ switch (lev) { case NOIND: - i = ElogDebugIndentLevel - 1; - if (i < 0) - i = 0; - if (i > 30) - i = i % 30; - cp = "DEBUG: "; + indent = ElogDebugIndentLevel - 1; + if (indent < 0) + indent = 0; + if (indent > 30) + indent = indent % 30; + prefix = "DEBUG: "; break; case DEBUG: - i = ElogDebugIndentLevel; - if (i < 0) - i = 0; - if (i > 30) - i = i % 30; - cp = "DEBUG: "; + indent = ElogDebugIndentLevel; + if (indent < 0) + indent = 0; + if (indent > 30) + indent = indent % 30; + prefix = "DEBUG: "; break; case NOTICE: - cp = "NOTICE: "; + prefix = "NOTICE: "; break; case ERROR: - cp = "ERROR: "; + prefix = "ERROR: "; break; default: - sprintf(line, "FATAL %d: ", lev); - cp = line; + /* temporarily use msg buf for prefix */ + sprintf(msg_fixedbuf, "FATAL %d: ", lev); + prefix = msg_fixedbuf; + break; + } + + /* get errno string for %m */ + if (errno < sys_nerr && errno >= 0) + errorstr = strerror(errno); + else + { + sprintf(errorstr_buf, "error %d", errno); + errorstr = errorstr_buf; + } + + /* + * 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) + indent + + strlen(fmt) + strlen(errorstr) + 1; + if (space_needed > (int) sizeof(fmt_fixedbuf)) + { + fmt_buf = (char *) malloc(space_needed); + if (fmt_buf == NULL) + { + /* We're up against it, convert to fatal out-of-memory error */ + fmt_buf = fmt_fixedbuf; + lev = REALLYFATAL; + fmt = "elog: out of memory"; /* this must fit in fmt_fixedbuf! */ + } } #ifdef ELOG_TIMESTAMPS - strcpy(buf, tprintf_timestamp()); - strcat(buf, cp); + strcpy(fmt_buf, tprintf_timestamp()); + strcat(fmt_buf, prefix); #else - strcpy(buf, cp); + strcpy(fmt_buf, prefix); #endif - bp = buf + strlen(buf); - while (i-- > 0) + bp = fmt_buf + strlen(fmt_buf); + while (indent-- > 0) *bp++ = ' '; for (cp = fmt; *cp; cp++) - if (*cp == '%' && *(cp + 1) == 'm') + { + if (cp[0] == '%' && cp[1] != '\0') { - if (errno < sys_nerr && errno >= 0) - strcpy(bp, strerror(errno)); + 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 - sprintf(bp, "error %d", errno); - bp += strlen(bp); - cp++; + { + /* copy % and next char --- this avoids trouble with %%m */ + *bp++ = *cp++; + *bp++ = *cp; + } } else *bp++ = *cp; + } *bp = '\0'; - vsnprintf(line, ELOG_MAXLEN - 1, buf, ap); - va_end(ap); + + /* + * 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 = (char *) malloc(space_needed); + if (msg_buf == NULL) + { + /* We're up against it, convert to fatal out-of-memory error */ + msg_buf = msg_fixedbuf; + lev = REALLYFATAL; +#ifdef ELOG_TIMESTAMPS + strcpy(msg_buf, tprintf_timestamp()); + strcat(msg_buf, "FATAL: elog: out of memory"); +#else + strcpy(msg_buf, "FATAL: elog: out of memory"); +#endif + break; + } + } + + /* + * Message prepared; send it where it should go + */ #ifdef USE_SYSLOG switch (lev) @@ -150,14 +269,16 @@ elog(int lev, const char *fmt,...) log_level = LOG_ERR; break; } - write_syslog(log_level, line + TIMESTAMP_SIZE); + write_syslog(log_level, msg_buf + TIMESTAMP_SIZE); #endif - len = strlen(strcat(line, "\n")); - if ((Debugfile > -1) && (UseSyslog <= 1)) - write(Debugfile, line, len); - if (lev == DEBUG || lev == NOIND) - return; + /* syslog doesn't want a trailing newline, but other destinations do */ + strcat(msg_buf, "\n"); + + len = strlen(msg_buf); + + if (Debugfile >= 0 && UseSyslog <= 1) + write(Debugfile, msg_buf, len); /* * If there's an error log file other than our channel to the @@ -167,33 +288,31 @@ elog(int lev, const char *fmt,...) * then writing here can cause this backend to exit without warning * that is, write() does an exit(). In this case, our only hope of * finding out what's going on is if Err_file was set to some disk - * log. This is a major pain. + * log. This is a major pain. (It's probably also long-dead code... + * does anyone still use ultrix?) */ - - if (Err_file > -1 && Debugfile != Err_file && (UseSyslog <= 1)) + if (lev > DEBUG && Err_file >= 0 && + Debugfile != Err_file && UseSyslog <= 1) { - if (write(Err_file, line, len) < 0) + if (write(Err_file, msg_buf, len) < 0) { - write(open("/dev/console", O_WRONLY, 0666), line, len); - fflush(stdout); - fflush(stderr); - proc_exit(lev); + write(open("/dev/console", O_WRONLY, 0666), msg_buf, len); + lev = REALLYFATAL; } fsync(Err_file); } #ifndef PG_STANDALONE - /* Send IPC message to the front-end program */ - if (IsUnderPostmaster && lev > DEBUG) + + if (lev > DEBUG && IsUnderPostmaster) { - /* notices are not errors, handle 'em differently */ + /* Send IPC message to the front-end program */ char msgtype; if (lev == NOTICE) msgtype = 'N'; else { - /* * Abort any COPY OUT in progress when an error is detected. * This hack is necessary because of poor design of copy @@ -203,7 +322,7 @@ elog(int lev, const char *fmt,...) msgtype = 'E'; } /* exclude the timestamp from msg sent to frontend */ - pq_puttextmessage(msgtype, line + TIMESTAMP_SIZE); + pq_puttextmessage(msgtype, msg_buf + TIMESTAMP_SIZE); /* * This flush is normally not necessary, since postgres.c will @@ -211,35 +330,45 @@ elog(int lev, const char *fmt,...) * 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 + * performance-critical path anyway, so an extra flush won't hurt * much ... */ pq_flush(); } - if (!IsUnderPostmaster) - { - /* - * There is no socket. One explanation for this is we are running - * as the Postmaster. So we'll write the message to stderr. + if (lev > DEBUG && ! IsUnderPostmaster) + { + /* We are running as an interactive backend, so just send + * the message to stderr. */ - fputs(line, stderr); + fputs(msg_buf, stderr); } + #endif /* !PG_STANDALONE */ + /* 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) { - ProcReleaseSpins(NULL); /* get rid of spinlocks we hold */ - if (!InError) + if (InError) { - /* exit to main loop */ - siglongjmp(Warn_restart, 1); + /* error reported during error recovery; don't loop forever */ + elog(REALLYFATAL, "elog: error during error recovery, giving up!"); } + /* exit to main loop */ + ProcReleaseSpins(NULL); /* get rid of spinlocks we hold */ + siglongjmp(Warn_restart, 1); } if (lev == FATAL) { - /* * Assume that if we have detected the failure we can exit with a * normal exit status. This will prevent the postmaster from @@ -254,13 +383,20 @@ elog(int lev, const char *fmt,...) if (lev > FATAL) { + /* + * Serious crash time. Postmaster will observe nonzero + * process exit status and kill the other backends too. + */ fflush(stdout); fflush(stderr); proc_exit(lev); } + + /* We reach here if lev <= NOTICE. OK to return to caller. */ } #ifndef PG_STANDALONE + int DebugFileOpen(void) { diff --git a/src/backend/utils/misc/trace.c b/src/backend/utils/misc/trace.c index baf8ce6121..3d9cbe607d 100644 --- a/src/backend/utils/misc/trace.c +++ b/src/backend/utils/misc/trace.c @@ -2,22 +2,21 @@ * * trace.c * - * Conditional trace ans logging functions. + * Conditional trace and logging functions. * * Massimo Dal Zotto * *------------------------------------------------------------------------- */ +#include "postgres.h" + #include #include #include #include #include #include - -#include "postgres.h" - #ifdef USE_SYSLOG #include #endif @@ -25,6 +24,13 @@ #include "miscadmin.h" #include "utils/trace.h" +/* + * We could support trace messages of indefinite length, as elog() does, + * but it's probably not worth the trouble. Instead limit trace message + * length to this. + */ +#define TRACEMSG_MAXLEN 1024 + #ifdef USE_SYSLOG /* * Global option to control the use of syslog(3) for logging: @@ -87,15 +93,14 @@ int tprintf(int flag, const char *fmt,...) { va_list ap; - char line[ELOG_MAXLEN + TIMESTAMP_SIZE + 1]; - + char line[TRACEMSG_MAXLEN + TIMESTAMP_SIZE + 1]; #ifdef USE_SYSLOG int log_level; #endif if ((flag == TRACE_ALL) || (pg_options[TRACE_ALL] > 0)) { - /* uconditional trace or trace all option set */ + /* unconditional trace or trace all option set */ } else if (pg_options[TRACE_ALL] == 0) { @@ -105,11 +110,11 @@ tprintf(int flag, const char *fmt,...) else if (pg_options[TRACE_ALL] < 0) return 0; - va_start(ap, fmt); #ifdef ELOG_TIMESTAMPS strcpy(line, tprintf_timestamp()); #endif - vsnprintf(line + TIMESTAMP_SIZE, ELOG_MAXLEN, fmt, ap); + va_start(ap, fmt); + vsnprintf(line + TIMESTAMP_SIZE, TRACEMSG_MAXLEN, fmt, ap); va_end(ap); #ifdef USE_SYSLOG @@ -134,13 +139,13 @@ int tprintf1(const char *fmt,...) { va_list ap; - char line[ELOG_MAXLEN + TIMESTAMP_SIZE + 1]; + char line[TRACEMSG_MAXLEN + TIMESTAMP_SIZE + 1]; - va_start(ap, fmt); #ifdef ELOG_TIMESTAMPS strcpy(line, tprintf_timestamp()); #endif - vsnprintf(line + TIMESTAMP_SIZE, ELOG_MAXLEN, fmt, ap); + va_start(ap, fmt); + vsnprintf(line + TIMESTAMP_SIZE, TRACEMSG_MAXLEN, fmt, ap); va_end(ap); #ifdef USE_SYSLOG @@ -164,13 +169,13 @@ int eprintf(const char *fmt,...) { va_list ap; - char line[ELOG_MAXLEN + TIMESTAMP_SIZE + 1]; + char line[TRACEMSG_MAXLEN + TIMESTAMP_SIZE + 1]; - va_start(ap, fmt); #ifdef ELOG_TIMESTAMPS strcpy(line, tprintf_timestamp()); #endif - vsnprintf(line + TIMESTAMP_SIZE, ELOG_MAXLEN, fmt, ap); + va_start(ap, fmt); + vsnprintf(line + TIMESTAMP_SIZE, TRACEMSG_MAXLEN, fmt, ap); va_end(ap); #ifdef USE_SYSLOG diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h index ae9ca20941..5f64a6b1c7 100644 --- a/src/include/utils/elog.h +++ b/src/include/utils/elog.h @@ -6,7 +6,7 @@ * * Copyright (c) 1994, Regents of the University of California * - * $Id: elog.h,v 1.11 1999/07/13 21:17:42 momjian Exp $ + * $Id: elog.h,v 1.12 1999/09/11 19:06:25 tgl Exp $ * *------------------------------------------------------------------------- */ @@ -14,36 +14,16 @@ #define ELOG_H #define NOTICE 0 /* random info - no special action */ -#define ERROR -1 /* user error - return to known state */ -#define FATAL 1 /* Fatal error - abort process */ -#define DEBUG -2 /* debug message */ -#define NOIND -3 /* debug message, don't indent as far */ - -#ifdef NOT_USED -#define PTIME 0x100 /* prepend time to message */ -#define POS 0x200 /* prepend source position to message */ -#define USERMSG 0x400 /* send message to user */ -#define TERM 0x800 /* send message to terminal */ -#define DBLOG 0x1000 /* put message in per db log */ -#define SLOG 0x2000 /* put message in system log */ -#define ABORTX 0x4000 /* abort process after logging */ -#endif - -/* Increase this to be able to use postmaster -d 3 with complex - * view definitions (which are transformed to very, very large INSERT statements - * and if -d 3 is used the query string of these statements is printed using - * vsprintf which expects enough memory reserved! */ -#define ELOG_MAXLEN 12288 +#define ERROR (-1) /* user error - return to known state */ +#define FATAL 1 /* fatal error - abort process */ +#define REALLYFATAL 2 /* take down the other backends with me */ +#define DEBUG (-2) /* debug message */ +#define NOIND (-3) /* debug message, don't indent as far */ - -/* uncomment the following if you want your elog's to be timestamped */ -/* #define ELOG_TIMESTAMPS */ - -extern void elog(int lev, const char *fmt,...); +extern void elog(int lev, const char *fmt, ...); #ifndef PG_STANDALONE -int DebugFileOpen(void); - +extern int DebugFileOpen(void); #endif #endif /* ELOG_H */ -- GitLab