Preliminary code cleanup in elog(). Split out some code into utility

[postgresql] / src / backend / utils / error / elog.c

/*-------------------------------------------------------------------------
 *
 * 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 <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>
#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;
}