From 1fadc727cc77d020e559b6a16db9db72d5678bf5 Mon Sep 17 00:00:00 2001 From: Sehrope Sarkuni Date: Wed, 1 Sep 2021 09:06:15 -0400 Subject: [PATCH 3/4] Split csv handling in elog.c into separate csvlog.c Split out csvlog to its own file and centralize common elog internals and helpers into its own file as well. --- src/backend/utils/error/Makefile | 1 + src/backend/utils/error/csvlog.c | 270 ++++++++++++++++++++++++++ src/backend/utils/error/elog.c | 313 ++---------------------------- src/include/utils/elog-internal.h | 78 ++++++++ 4 files changed, 365 insertions(+), 297 deletions(-) create mode 100644 src/backend/utils/error/csvlog.c create mode 100644 src/include/utils/elog-internal.h diff --git a/src/backend/utils/error/Makefile b/src/backend/utils/error/Makefile index 612da215d0..ef770dd2f2 100644 --- a/src/backend/utils/error/Makefile +++ b/src/backend/utils/error/Makefile @@ -14,6 +14,7 @@ include $(top_builddir)/src/Makefile.global OBJS = \ assert.o \ + csvlog.o \ elog.o include $(top_srcdir)/src/backend/common.mk diff --git a/src/backend/utils/error/csvlog.c b/src/backend/utils/error/csvlog.c new file mode 100644 index 0000000000..923b7e7d73 --- /dev/null +++ b/src/backend/utils/error/csvlog.c @@ -0,0 +1,270 @@ +/*------------------------------------------------------------------------- + * + * csvlog.c + * CSV logging + * + * Copyright (c) 2021, PostgreSQL Global Development Group + * Portions Copyright (c) 1994, Regents of the University of California + * + * + * IDENTIFICATION + * src/backend/utils/error/csvlog.c + * + *------------------------------------------------------------------------- + */ +#include "postgres.h" + +#include "access/xact.h" +#include "libpq/libpq.h" +#include "lib/stringinfo.h" +#include "miscadmin.h" +#include "postmaster/bgworker.h" +#include "postmaster/syslogger.h" +#include "storage/lock.h" +#include "storage/proc.h" +#include "tcop/tcopprot.h" +#include "utils/backend_status.h" +#include "utils/elog-internal.h" +#include "utils/guc.h" +#include "utils/ps_status.h" + +/* + * append a CSV'd version of a string to a StringInfo + * We use the PostgreSQL defaults for CSV, i.e. quote = escape = '"' + * If it's NULL, append nothing. + */ +static inline void +appendCSVLiteral(StringInfo buf, const char *data) +{ + const char *p = data; + char c; + + /* avoid confusing an empty string with NULL */ + if (p == NULL) + return; + + appendStringInfoCharMacro(buf, '"'); + while ((c = *p++) != '\0') + { + if (c == '"') + appendStringInfoCharMacro(buf, '"'); + appendStringInfoCharMacro(buf, c); + } + appendStringInfoCharMacro(buf, '"'); +} + +/* + * Constructs the error message, depending on the Errordata it gets, in a CSV + * format which is described in doc/src/sgml/config.sgml. + */ +void +write_csvlog(ErrorData *edata) +{ + StringInfoData buf; + bool print_stmt = false; + + /* static counter for line numbers */ + static long log_line_number = 0; + + /* has counter been reset in current process? */ + static int log_my_pid = 0; + + /* + * This is one of the few places where we'd rather not inherit a static + * variable's value from the postmaster. But since we will, reset it when + * MyProcPid changes. + */ + if (log_my_pid != MyProcPid) + { + log_line_number = 0; + log_my_pid = MyProcPid; + formatted_start_time[0] = '\0'; + } + log_line_number++; + + initStringInfo(&buf); + + /* + * timestamp with milliseconds + * + * Check if the timestamp is already calculated for the syslog message, + * and use it if so. Otherwise, get the current timestamp. This is done + * to put same timestamp in both syslog and csvlog messages. + */ + if (formatted_log_time[0] == '\0') + setup_formatted_log_time(); + + appendStringInfoString(&buf, formatted_log_time); + appendStringInfoChar(&buf, ','); + + /* username */ + if (MyProcPort) + appendCSVLiteral(&buf, MyProcPort->user_name); + appendStringInfoChar(&buf, ','); + + /* database name */ + if (MyProcPort) + appendCSVLiteral(&buf, MyProcPort->database_name); + appendStringInfoChar(&buf, ','); + + /* Process id */ + if (MyProcPid != 0) + appendStringInfo(&buf, "%d", MyProcPid); + appendStringInfoChar(&buf, ','); + + /* Remote host and port */ + if (MyProcPort && MyProcPort->remote_host) + { + appendStringInfoChar(&buf, '"'); + appendStringInfoString(&buf, MyProcPort->remote_host); + if (MyProcPort->remote_port && MyProcPort->remote_port[0] != '\0') + { + appendStringInfoChar(&buf, ':'); + appendStringInfoString(&buf, MyProcPort->remote_port); + } + appendStringInfoChar(&buf, '"'); + } + appendStringInfoChar(&buf, ','); + + /* session id */ + appendStringInfo(&buf, "%lx.%x", (long) MyStartTime, MyProcPid); + appendStringInfoChar(&buf, ','); + + /* Line number */ + appendStringInfo(&buf, "%ld", log_line_number); + appendStringInfoChar(&buf, ','); + + /* PS display */ + if (MyProcPort) + { + StringInfoData msgbuf; + const char *psdisp; + int displen; + + initStringInfo(&msgbuf); + + psdisp = get_ps_display(&displen); + appendBinaryStringInfo(&msgbuf, psdisp, displen); + appendCSVLiteral(&buf, msgbuf.data); + + pfree(msgbuf.data); + } + appendStringInfoChar(&buf, ','); + + /* session start timestamp */ + if (formatted_start_time[0] == '\0') + setup_formatted_start_time(); + appendStringInfoString(&buf, formatted_start_time); + appendStringInfoChar(&buf, ','); + + /* Virtual transaction id */ + /* keep VXID format in sync with lockfuncs.c */ + if (MyProc != NULL && MyProc->backendId != InvalidBackendId) + appendStringInfo(&buf, "%d/%u", MyProc->backendId, MyProc->lxid); + appendStringInfoChar(&buf, ','); + + /* Transaction id */ + appendStringInfo(&buf, "%u", GetTopTransactionIdIfAny()); + appendStringInfoChar(&buf, ','); + + /* Error severity */ + appendStringInfoString(&buf, _(error_severity(edata->elevel))); + appendStringInfoChar(&buf, ','); + + /* SQL state code */ + appendStringInfoString(&buf, unpack_sql_state(edata->sqlerrcode)); + appendStringInfoChar(&buf, ','); + + /* errmessage */ + appendCSVLiteral(&buf, edata->message); + appendStringInfoChar(&buf, ','); + + /* errdetail or errdetail_log */ + if (edata->detail_log) + appendCSVLiteral(&buf, edata->detail_log); + else + appendCSVLiteral(&buf, edata->detail); + appendStringInfoChar(&buf, ','); + + /* errhint */ + appendCSVLiteral(&buf, edata->hint); + appendStringInfoChar(&buf, ','); + + /* internal query */ + appendCSVLiteral(&buf, edata->internalquery); + appendStringInfoChar(&buf, ','); + + /* if printed internal query, print internal pos too */ + if (edata->internalpos > 0 && edata->internalquery != NULL) + appendStringInfo(&buf, "%d", edata->internalpos); + appendStringInfoChar(&buf, ','); + + /* errcontext */ + if (!edata->hide_ctx) + appendCSVLiteral(&buf, edata->context); + appendStringInfoChar(&buf, ','); + + /* user query --- only reported if not disabled by the caller */ + if (is_log_level_output(edata->elevel, log_min_error_statement) && + debug_query_string != NULL && + !edata->hide_stmt) + print_stmt = true; + if (print_stmt) + appendCSVLiteral(&buf, debug_query_string); + appendStringInfoChar(&buf, ','); + if (print_stmt && edata->cursorpos > 0) + appendStringInfo(&buf, "%d", edata->cursorpos); + appendStringInfoChar(&buf, ','); + + /* file error location */ + if (Log_error_verbosity >= PGERROR_VERBOSE) + { + StringInfoData msgbuf; + + initStringInfo(&msgbuf); + + if (edata->funcname && edata->filename) + appendStringInfo(&msgbuf, "%s, %s:%d", + edata->funcname, edata->filename, + edata->lineno); + else if (edata->filename) + appendStringInfo(&msgbuf, "%s:%d", + edata->filename, edata->lineno); + appendCSVLiteral(&buf, msgbuf.data); + pfree(msgbuf.data); + } + appendStringInfoChar(&buf, ','); + + /* application name */ + if (application_name) + appendCSVLiteral(&buf, application_name); + + appendStringInfoChar(&buf, ','); + + /* backend type */ + appendCSVLiteral(&buf, get_backend_type_for_log()); + appendStringInfoChar(&buf, ','); + + /* leader PID */ + if (MyProc) + { + PGPROC *leader = MyProc->lockGroupLeader; + + /* + * Show the leader only for active parallel workers. This leaves out + * the leader of a parallel group. + */ + if (leader && leader->pid != MyProcPid) + appendStringInfo(&buf, "%d", leader->pid); + } + appendStringInfoChar(&buf, ','); + + /* query id */ + appendStringInfo(&buf, "%lld", (long long) pgstat_get_my_query_id()); + + appendStringInfoChar(&buf, '\n'); + + write_syslogger(buf.data, buf.len, LOG_DESTINATION_CSVLOG); + + pfree(buf.data); +} diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c index cd13111708..47d6677827 100644 --- a/src/backend/utils/error/elog.c +++ b/src/backend/utils/error/elog.c @@ -82,7 +82,7 @@ #include "utils/guc.h" #include "utils/memutils.h" #include "utils/ps_status.h" - +#include "utils/elog-internal.h" /* In this module, access gettext() via err_gettext() */ #undef _ @@ -155,9 +155,8 @@ static int recursion_depth = 0; /* to detect actual recursion */ static struct timeval saved_timeval; static bool saved_timeval_set = false; -#define FORMATTED_TS_LEN 128 -static char formatted_start_time[FORMATTED_TS_LEN]; -static char formatted_log_time[FORMATTED_TS_LEN]; +char formatted_start_time[FORMATTED_TS_LEN]; +char formatted_log_time[FORMATTED_TS_LEN]; /* Macro for checking errordata_stack_depth is reasonable */ @@ -175,52 +174,13 @@ static const char *err_gettext(const char *str) pg_attribute_format_arg(1); static pg_noinline void set_backtrace(ErrorData *edata, int num_skip); static void set_errdata_field(MemoryContextData *cxt, char **ptr, const char *str); static void write_console(const char *line, int len); -static void setup_formatted_log_time(void); -static void setup_formatted_start_time(void); static const char *process_log_prefix_padding(const char *p, int *padding); static void log_line_prefix(StringInfo buf, ErrorData *edata); -static void write_csvlog(ErrorData *edata); static void send_message_to_server_log(ErrorData *edata); static void write_pipe_chunks(char *data, int len, int dest); static void send_message_to_frontend(ErrorData *edata); -static const char *error_severity(int elevel); static void append_with_tabs(StringInfo buf, const char *str); - -/* - * is_log_level_output -- is elevel logically >= log_min_level? - * - * We use this for tests that should consider LOG to sort out-of-order, - * between ERROR and FATAL. Generally this is the right thing for testing - * whether a message should go to the postmaster log, whereas a simple >= - * test is correct for testing whether the message should go to the client. - */ -static inline bool -is_log_level_output(int elevel, int log_min_level) -{ - if (elevel == LOG || elevel == LOG_SERVER_ONLY) - { - if (log_min_level == LOG || log_min_level <= ERROR) - return true; - } - else if (elevel == WARNING_CLIENT_ONLY) - { - /* never sent to log, regardless of log_min_level */ - return false; - } - else if (log_min_level == LOG) - { - /* elevel != LOG */ - if (elevel >= FATAL) - return true; - } - /* Neither is LOG */ - else if (elevel >= log_min_level) - return true; - - return false; -} - /* * Policy-setting subroutines. These are fairly simple, but it seems wise * to have the code in just one place. @@ -2291,7 +2251,7 @@ write_console(const char *line, int len) /* * setup formatted_log_time, for consistent times between CSV and regular logs */ -static void +void setup_formatted_log_time(void) { pg_time_t stamp_time; @@ -2323,7 +2283,7 @@ setup_formatted_log_time(void) /* * setup formatted_start_time */ -static void +void setup_formatted_start_time(void) { pg_time_t stamp_time = (pg_time_t) MyStartTime; @@ -2729,257 +2689,6 @@ log_line_prefix(StringInfo buf, ErrorData *edata) } } -/* - * append a CSV'd version of a string to a StringInfo - * We use the PostgreSQL defaults for CSV, i.e. quote = escape = '"' - * If it's NULL, append nothing. - */ -static inline void -appendCSVLiteral(StringInfo buf, const char *data) -{ - const char *p = data; - char c; - - /* avoid confusing an empty string with NULL */ - if (p == NULL) - return; - - appendStringInfoCharMacro(buf, '"'); - while ((c = *p++) != '\0') - { - if (c == '"') - appendStringInfoCharMacro(buf, '"'); - appendStringInfoCharMacro(buf, c); - } - appendStringInfoCharMacro(buf, '"'); -} - -/* - * Constructs the error message, depending on the Errordata it gets, in a CSV - * format which is described in doc/src/sgml/config.sgml. - */ -static void -write_csvlog(ErrorData *edata) -{ - StringInfoData buf; - bool print_stmt = false; - - /* static counter for line numbers */ - static long log_line_number = 0; - - /* has counter been reset in current process? */ - static int log_my_pid = 0; - - /* - * This is one of the few places where we'd rather not inherit a static - * variable's value from the postmaster. But since we will, reset it when - * MyProcPid changes. - */ - if (log_my_pid != MyProcPid) - { - log_line_number = 0; - log_my_pid = MyProcPid; - formatted_start_time[0] = '\0'; - } - log_line_number++; - - initStringInfo(&buf); - - /* - * timestamp with milliseconds - * - * Check if the timestamp is already calculated for the syslog message, - * and use it if so. Otherwise, get the current timestamp. This is done - * to put same timestamp in both syslog and csvlog messages. - */ - if (formatted_log_time[0] == '\0') - setup_formatted_log_time(); - - appendStringInfoString(&buf, formatted_log_time); - appendStringInfoChar(&buf, ','); - - /* username */ - if (MyProcPort) - appendCSVLiteral(&buf, MyProcPort->user_name); - appendStringInfoChar(&buf, ','); - - /* database name */ - if (MyProcPort) - appendCSVLiteral(&buf, MyProcPort->database_name); - appendStringInfoChar(&buf, ','); - - /* Process id */ - if (MyProcPid != 0) - appendStringInfo(&buf, "%d", MyProcPid); - appendStringInfoChar(&buf, ','); - - /* Remote host and port */ - if (MyProcPort && MyProcPort->remote_host) - { - appendStringInfoChar(&buf, '"'); - appendStringInfoString(&buf, MyProcPort->remote_host); - if (MyProcPort->remote_port && MyProcPort->remote_port[0] != '\0') - { - appendStringInfoChar(&buf, ':'); - appendStringInfoString(&buf, MyProcPort->remote_port); - } - appendStringInfoChar(&buf, '"'); - } - appendStringInfoChar(&buf, ','); - - /* session id */ - appendStringInfo(&buf, "%lx.%x", (long) MyStartTime, MyProcPid); - appendStringInfoChar(&buf, ','); - - /* Line number */ - appendStringInfo(&buf, "%ld", log_line_number); - appendStringInfoChar(&buf, ','); - - /* PS display */ - if (MyProcPort) - { - StringInfoData msgbuf; - const char *psdisp; - int displen; - - initStringInfo(&msgbuf); - - psdisp = get_ps_display(&displen); - appendBinaryStringInfo(&msgbuf, psdisp, displen); - appendCSVLiteral(&buf, msgbuf.data); - - pfree(msgbuf.data); - } - appendStringInfoChar(&buf, ','); - - /* session start timestamp */ - if (formatted_start_time[0] == '\0') - setup_formatted_start_time(); - appendStringInfoString(&buf, formatted_start_time); - appendStringInfoChar(&buf, ','); - - /* Virtual transaction id */ - /* keep VXID format in sync with lockfuncs.c */ - if (MyProc != NULL && MyProc->backendId != InvalidBackendId) - appendStringInfo(&buf, "%d/%u", MyProc->backendId, MyProc->lxid); - appendStringInfoChar(&buf, ','); - - /* Transaction id */ - appendStringInfo(&buf, "%u", GetTopTransactionIdIfAny()); - appendStringInfoChar(&buf, ','); - - /* Error severity */ - appendStringInfoString(&buf, _(error_severity(edata->elevel))); - appendStringInfoChar(&buf, ','); - - /* SQL state code */ - appendStringInfoString(&buf, unpack_sql_state(edata->sqlerrcode)); - appendStringInfoChar(&buf, ','); - - /* errmessage */ - appendCSVLiteral(&buf, edata->message); - appendStringInfoChar(&buf, ','); - - /* errdetail or errdetail_log */ - if (edata->detail_log) - appendCSVLiteral(&buf, edata->detail_log); - else - appendCSVLiteral(&buf, edata->detail); - appendStringInfoChar(&buf, ','); - - /* errhint */ - appendCSVLiteral(&buf, edata->hint); - appendStringInfoChar(&buf, ','); - - /* internal query */ - appendCSVLiteral(&buf, edata->internalquery); - appendStringInfoChar(&buf, ','); - - /* if printed internal query, print internal pos too */ - if (edata->internalpos > 0 && edata->internalquery != NULL) - appendStringInfo(&buf, "%d", edata->internalpos); - appendStringInfoChar(&buf, ','); - - /* errcontext */ - if (!edata->hide_ctx) - appendCSVLiteral(&buf, edata->context); - appendStringInfoChar(&buf, ','); - - /* user query --- only reported if not disabled by the caller */ - if (is_log_level_output(edata->elevel, log_min_error_statement) && - debug_query_string != NULL && - !edata->hide_stmt) - print_stmt = true; - if (print_stmt) - appendCSVLiteral(&buf, debug_query_string); - appendStringInfoChar(&buf, ','); - if (print_stmt && edata->cursorpos > 0) - appendStringInfo(&buf, "%d", edata->cursorpos); - appendStringInfoChar(&buf, ','); - - /* file error location */ - if (Log_error_verbosity >= PGERROR_VERBOSE) - { - StringInfoData msgbuf; - - initStringInfo(&msgbuf); - - if (edata->funcname && edata->filename) - appendStringInfo(&msgbuf, "%s, %s:%d", - edata->funcname, edata->filename, - edata->lineno); - else if (edata->filename) - appendStringInfo(&msgbuf, "%s:%d", - edata->filename, edata->lineno); - appendCSVLiteral(&buf, msgbuf.data); - pfree(msgbuf.data); - } - appendStringInfoChar(&buf, ','); - - /* application name */ - if (application_name) - appendCSVLiteral(&buf, application_name); - - appendStringInfoChar(&buf, ','); - - /* backend type */ - if (MyProcPid == PostmasterPid) - appendCSVLiteral(&buf, "postmaster"); - else if (MyBackendType == B_BG_WORKER) - appendCSVLiteral(&buf, MyBgworkerEntry->bgw_type); - else - appendCSVLiteral(&buf, GetBackendTypeDesc(MyBackendType)); - - appendStringInfoChar(&buf, ','); - - /* leader PID */ - if (MyProc) - { - PGPROC *leader = MyProc->lockGroupLeader; - - /* - * Show the leader only for active parallel workers. This leaves out - * the leader of a parallel group. - */ - if (leader && leader->pid != MyProcPid) - appendStringInfo(&buf, "%d", leader->pid); - } - appendStringInfoChar(&buf, ','); - - /* query id */ - appendStringInfo(&buf, "%lld", (long long) pgstat_get_my_query_id()); - - appendStringInfoChar(&buf, '\n'); - - /* If in the syslogger process, try to write messages direct to file */ - if (MyBackendType == B_LOGGER) - write_syslogger_file(buf.data, buf.len, LOG_DESTINATION_CSVLOG); - else - write_pipe_chunks(buf.data, buf.len, LOG_DESTINATION_CSVLOG); - - pfree(buf.data); -} - /* * Unpack MAKE_SQLSTATE code. Note that this returns a pointer to a * static buffer. @@ -3273,6 +2982,16 @@ write_pipe_chunks(char *data, int len, int dest) (void) rc; } +void +write_syslogger(char *data, int len, int dest) +{ + /* If in the syslogger process, try to write messages direct to file */ + if (MyBackendType == B_LOGGER) + write_syslogger_file(data, len, dest); + else + write_pipe_chunks(data, len, dest); +} + /* * Append a text string to the error report being built for the client. @@ -3483,7 +3202,7 @@ send_message_to_frontend(ErrorData *edata) * The string is not localized here, but we mark the strings for translation * so that callers can invoke _() on the result. */ -static const char * +const char * error_severity(int elevel) { const char *prefix; diff --git a/src/include/utils/elog-internal.h b/src/include/utils/elog-internal.h new file mode 100644 index 0000000000..ac08b6f12f --- /dev/null +++ b/src/include/utils/elog-internal.h @@ -0,0 +1,78 @@ +/*------------------------------------------------------------------------- + * + * elog-internal.h + * POSTGRES error reporting/logging internal definitions. + * + * + * Portions Copyright (c) 2021, PostgreSQL Global Development Group + * src/include/utils/elog-internal.h + * + *------------------------------------------------------------------------- + */ +#ifndef ELOG_INTERNAL_H +#define ELOG_INTERNAL_H + +#include "postgres.h" + +#include "utils/elog.h" +#include "miscadmin.h" +#include "postmaster/postmaster.h" +#include "postmaster/bgworker.h" + +const char * error_severity(int elevel); +void write_syslogger(char *data, int len, int dest); + +void write_csvlog(ErrorData *edata); + +/* + * is_log_level_output -- is elevel logically >= log_min_level? + * + * We use this for tests that should consider LOG to sort out-of-order, + * between ERROR and FATAL. Generally this is the right thing for testing + * whether a message should go to the postmaster log, whereas a simple >= + * test is correct for testing whether the message should go to the client. + */ +static inline bool +is_log_level_output(int elevel, int log_min_level) +{ + if (elevel == LOG || elevel == LOG_SERVER_ONLY) + { + if (log_min_level == LOG || log_min_level <= ERROR) + return true; + } + else if (elevel == WARNING_CLIENT_ONLY) + { + /* never sent to log, regardless of log_min_level */ + return false; + } + else if (log_min_level == LOG) + { + /* elevel != LOG */ + if (elevel >= FATAL) + return true; + } + /* Neither is LOG */ + else if (elevel >= log_min_level) + return true; + + return false; +} + +static inline const char * +get_backend_type_for_log() { + if (MyProcPid == PostmasterPid) + return "postmaster"; + else if (MyBackendType == B_BG_WORKER) + return MyBgworkerEntry->bgw_type; + else + return GetBackendTypeDesc(MyBackendType); +} + +#define FORMATTED_TS_LEN 128 +extern char formatted_start_time[FORMATTED_TS_LEN]; +extern char formatted_log_time[FORMATTED_TS_LEN]; + +void setup_formatted_log_time(void); +void setup_formatted_start_time(void); + +#endif -- 2.17.1