On Fri, Sep 10, 2021 at 03:56:18PM +0900, Michael Paquier wrote: > And this part leads me to the attached, where the addition of the JSON > format would result in the addition of a couple of lines.
Okay, I have worked through the first half of the patch set, and
applied the improved versions of 0001 (refactoring of the chunk
protocol) and 0002 (addition of the tests for csvlog).
I have not looked in details at 0003 and 0004 yet. Still, here are
some comments after a quick scan.
+ * elog-internal.h
I'd rather avoid the hyphen, and use elog_internal.h.
+#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);
We could just use a static buffer in each one of those routines, and
return back a pointer to the caller.
+ else if ((Log_destination & LOG_DESTINATION_JSONLOG) &&
+ (jsonlogFile == NULL ||
+ time_based_rotation || (size_rotation_for & LOG_DESTINATION_JSONLOG)))
[...]
+ /* Write to JSON log if enabled */
+ else if (Log_destination & LOG_DESTINATION_JSONLOG)
+ {
Those bits in 0004 are wrong. They should be two "if" clauses. This
is leading to issues when setting log_destination to multiple values
with jsonlog in the set of values and logging_connector = on, and the
logs are not getting redirected properly to the .json file. We would
get the data for the .log and .csv files though. This issue also
happens with the original patch set applied on top of e757080. I
think that we should also be more careful with the way we free
StringInfoData in send_message_to_server_log(), or we are going to
finish with unwelcome leaks.
The same coding pattern is now repeated three times in logfile_rotate():
- Check if a logging type is enabled.
- Optionally open new file, with logfile_open().
- Business with ENFILE and EMFILE.
- pfree() and save of the static FILE* ane file name for each type.
I think that we have enough material for a wrapper routine that does
this work, where we pass down LOG_DESTINATION_* and pointers to the
static FILE* and the static last file names. That would have avoided
the bug I found above.
The rebased patch set, that has reworked the tests to be in line with
HEAD, also fails. They compile.
Sehrope, could you adjust that?
--
Michael
From a08e9df54c5960225055a0c999090dad8cf839be Mon Sep 17 00:00:00 2001
From: Sehrope Sarkuni <sehr...@jackdb.com>
Date: Wed, 1 Sep 2021 09:06:15 -0400
Subject: [PATCH v3 1/2] 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/include/utils/elog-internal.h | 78 ++++++++
src/backend/utils/error/Makefile | 1 +
src/backend/utils/error/csvlog.c | 270 ++++++++++++++++++++++++++
src/backend/utils/error/elog.c | 313 ++----------------------------
4 files changed, 365 insertions(+), 297 deletions(-)
create mode 100644 src/include/utils/elog-internal.h
create mode 100644 src/backend/utils/error/csvlog.c
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
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 2af87ee3bd..68fb167976 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.
@@ -3276,6 +2985,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.
@@ -3475,7 +3194,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;
--
2.33.0
From 823aab1f809a47f1a525a6ad8ae0366fd07328b6 Mon Sep 17 00:00:00 2001
From: Michael Paquier <mich...@paquier.xyz>
Date: Mon, 13 Sep 2021 10:41:55 +0900
Subject: [PATCH v3 2/2] Add jsonlog log_destination for JSON server logs
Adds option to write server log files as JSON. Each log entry is written as its
own line with any internal newlines escaped as \n. Other non-ASCII and special
characters are also escaped using standard JSON escape sequences.
JSON logging is enabled by setting the GUC log_destination to "jsonlog" and
defaults to a log file with a ".json" extension.
---
src/include/postmaster/syslogger.h | 1 +
src/include/utils/elog-internal.h | 1 +
src/include/utils/elog.h | 1 +
src/backend/postmaster/syslogger.c | 182 +++++++++++++++--
src/backend/utils/adt/misc.c | 5 +-
src/backend/utils/error/Makefile | 3 +-
src/backend/utils/error/elog.c | 26 +++
src/backend/utils/error/jsonlog.c | 312 +++++++++++++++++++++++++++++
src/backend/utils/misc/guc.c | 2 +
src/bin/pg_ctl/t/004_logrotate.pl | 12 +-
doc/src/sgml/config.sgml | 67 ++++++-
11 files changed, 585 insertions(+), 27 deletions(-)
create mode 100644 src/backend/utils/error/jsonlog.c
diff --git a/src/include/postmaster/syslogger.h
b/src/include/postmaster/syslogger.h
index c79dfbeba2..18448b76e5 100644
--- a/src/include/postmaster/syslogger.h
+++ b/src/include/postmaster/syslogger.h
@@ -64,6 +64,7 @@ typedef union
/* log destinations */
#define PIPE_PROTO_DEST_STDERR 0x10
#define PIPE_PROTO_DEST_CSVLOG 0x20
+#define PIPE_PROTO_DEST_JSONLOG 0x40
/* GUC options */
extern bool Logging_collector;
diff --git a/src/include/utils/elog-internal.h
b/src/include/utils/elog-internal.h
index ac08b6f12f..13c217a29d 100644
--- a/src/include/utils/elog-internal.h
+++ b/src/include/utils/elog-internal.h
@@ -23,6 +23,7 @@ const char * error_severity(int elevel);
void write_syslogger(char *data, int len, int dest);
void write_csvlog(ErrorData *edata);
+void write_jsonlog(ErrorData *edata);
/*
* is_log_level_output -- is elevel logically >= log_min_level?
diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h
index f53607e12e..c0c699f485 100644
--- a/src/include/utils/elog.h
+++ b/src/include/utils/elog.h
@@ -436,6 +436,7 @@ extern bool syslog_split_messages;
#define LOG_DESTINATION_SYSLOG 2
#define LOG_DESTINATION_EVENTLOG 4
#define LOG_DESTINATION_CSVLOG 8
+#define LOG_DESTINATION_JSONLOG 16
/* Other exported functions */
extern void DebugFileOpen(void);
diff --git a/src/backend/postmaster/syslogger.c
b/src/backend/postmaster/syslogger.c
index bca3883572..c0ce072900 100644
--- a/src/backend/postmaster/syslogger.c
+++ b/src/backend/postmaster/syslogger.c
@@ -86,9 +86,11 @@ static bool pipe_eof_seen = false;
static bool rotation_disabled = false;
static FILE *syslogFile = NULL;
static FILE *csvlogFile = NULL;
+static FILE *jsonlogFile = NULL;
NON_EXEC_STATIC pg_time_t first_syslogger_file_time = 0;
static char *last_file_name = NULL;
static char *last_csv_file_name = NULL;
+static char *last_json_file_name = NULL;
/*
* Buffers for saving partial messages from different backends.
@@ -275,6 +277,8 @@ SysLoggerMain(int argc, char *argv[])
last_file_name = logfile_getname(first_syslogger_file_time, NULL);
if (csvlogFile != NULL)
last_csv_file_name = logfile_getname(first_syslogger_file_time,
".csv");
+ if (jsonlogFile != NULL)
+ last_json_file_name =
logfile_getname(first_syslogger_file_time, ".json");
/* remember active logfile parameters */
currentLogDir = pstrdup(Log_directory);
@@ -361,6 +365,14 @@ SysLoggerMain(int argc, char *argv[])
(csvlogFile != NULL))
rotation_requested = true;
+ /*
+ * Force a rotation if JSONLOG output was just turned
on or off and
+ * we need to open or close jsonlogFile accordingly.
+ */
+ if (((Log_destination & LOG_DESTINATION_JSONLOG) != 0)
!=
+ (jsonlogFile != NULL))
+ rotation_requested = true;
+
/*
* If rotation time parameter changed, reset next
rotation time,
* but don't immediately force a rotation.
@@ -411,6 +423,12 @@ SysLoggerMain(int argc, char *argv[])
rotation_requested = true;
size_rotation_for |= LOG_DESTINATION_CSVLOG;
}
+ if (jsonlogFile != NULL &&
+ ftell(jsonlogFile) >= Log_RotationSize * 1024L)
+ {
+ rotation_requested = true;
+ size_rotation_for |= LOG_DESTINATION_JSONLOG;
+ }
}
if (rotation_requested)
@@ -420,7 +438,7 @@ SysLoggerMain(int argc, char *argv[])
* was sent by pg_rotate_logfile() or "pg_ctl
logrotate".
*/
if (!time_based_rotation && size_rotation_for == 0)
- size_rotation_for = LOG_DESTINATION_STDERR |
LOG_DESTINATION_CSVLOG;
+ size_rotation_for = LOG_DESTINATION_STDERR |
LOG_DESTINATION_CSVLOG | LOG_DESTINATION_JSONLOG;
logfile_rotate(time_based_rotation, size_rotation_for);
}
@@ -626,6 +644,20 @@ SysLogger_Start(void)
pfree(filename);
}
+ /*
+ * Likewise for the initial JSON log file, if that's enabled. (Note
that
+ * we open syslogFile even when only JSON output is nominally enabled,
+ * since some code paths will write to syslogFile anyway.)
+ */
+ if (Log_destination & LOG_DESTINATION_JSONLOG)
+ {
+ filename = logfile_getname(first_syslogger_file_time, ".json");
+
+ jsonlogFile = logfile_open(filename, "a", false);
+
+ pfree(filename);
+ }
+
#ifdef EXEC_BACKEND
switch ((sysloggerPid = syslogger_forkexec()))
#else
@@ -723,6 +755,11 @@ SysLogger_Start(void)
fclose(csvlogFile);
csvlogFile = NULL;
}
+ if (jsonlogFile != NULL)
+ {
+ fclose(jsonlogFile);
+ jsonlogFile = NULL;
+ }
return (int) sysloggerPid;
}
@@ -745,6 +782,7 @@ syslogger_forkexec(void)
int ac = 0;
char filenobuf[32];
char csvfilenobuf[32];
+ char jsonfilenobuf[32];
av[ac++] = "postgres";
av[ac++] = "--forklog";
@@ -772,14 +810,25 @@ syslogger_forkexec(void)
fileno(csvlogFile));
else
strcpy(csvfilenobuf, "-1");
+ if (jsonlogFile != NULL)
+ snprintf(jsonfilenobuf, sizeof(jsonfilenobuf), "%d",
+ fileno(jsonlogFile));
+ else
+ strcpy(jsonfilenobuf, "-1");
#else /* WIN32 */
if (csvlogFile != NULL)
snprintf(csvfilenobuf, sizeof(csvfilenobuf), "%ld",
(long) _get_osfhandle(_fileno(csvlogFile)));
else
strcpy(csvfilenobuf, "0");
+ if (jsonlogFile != NULL)
+ snprintf(jsonfilenobuf, sizeof(jsonfilenobuf), "%ld",
+ (long) _get_osfhandle(_fileno(jsonlogFile)));
+ else
+ strcpy(jsonfilenobuf, "0");
#endif /* WIN32 */
av[ac++] = csvfilenobuf;
+ av[ac++] = jsonfilenobuf;
av[ac] = NULL;
Assert(ac < lengthof(av));
@@ -797,8 +846,8 @@ syslogger_parseArgs(int argc, char *argv[])
{
int fd;
- Assert(argc == 5);
- argv += 3;
+ Assert(argc == 6);
+ argv += 4;
/*
* Re-open the error output files that were opened by SysLogger_Start().
@@ -820,6 +869,12 @@ syslogger_parseArgs(int argc, char *argv[])
csvlogFile = fdopen(fd, "a");
setvbuf(csvlogFile, NULL, PG_IOLBF, 0);
}
+ fd = atoi(*argv++);
+ if (fd != -1)
+ {
+ jsonlogFile = fdopen(fd, "a");
+ setvbuf(jsonlogFile, NULL, PG_IOLBF, 0);
+ }
#else /* WIN32 */
fd = atoi(*argv++);
if (fd != 0)
@@ -841,6 +896,16 @@ syslogger_parseArgs(int argc, char *argv[])
setvbuf(csvlogFile, NULL, PG_IOLBF, 0);
}
}
+ fd = atoi(*argv++);
+ if (fd != 0)
+ {
+ fd = _open_osfhandle(fd, _O_APPEND | _O_TEXT);
+ if (fd > 0)
+ {
+ jsonlogFile = fdopen(fd, "a");
+ setvbuf(jsonlogFile, NULL, PG_IOLBF, 0);
+ }
+ }
#endif /* WIN32 */
}
#endif /* EXEC_BACKEND */
@@ -890,7 +955,9 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
/* Do we have a valid header? */
memcpy(&p, cursor, offsetof(PipeProtoHeader, data));
- dest_flags = p.flags & (PIPE_PROTO_DEST_STDERR |
PIPE_PROTO_DEST_CSVLOG);
+ dest_flags = p.flags & (PIPE_PROTO_DEST_STDERR |
+
PIPE_PROTO_DEST_CSVLOG |
+
PIPE_PROTO_DEST_JSONLOG);
if (p.nuls[0] == '\0' && p.nuls[1] == '\0' &&
p.len > 0 && p.len <= PIPE_MAX_PAYLOAD &&
p.pid != 0 &&
@@ -912,6 +979,8 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
dest = LOG_DESTINATION_STDERR;
else if ((p.flags & PIPE_PROTO_DEST_CSVLOG) != 0)
dest = LOG_DESTINATION_CSVLOG;
+ else if ((p.flags & PIPE_PROTO_DEST_JSONLOG) != 0)
+ dest = LOG_DESTINATION_JSONLOG;
else
{
/* this should never happen as of the header
validation */
@@ -1091,19 +1160,23 @@ write_syslogger_file(const char *buffer, int count, int
destination)
FILE *logfile;
/*
- * If we're told to write to csvlogFile, but it's not open, dump the
data
- * to syslogFile (which is always open) instead. This can happen if CSV
+ * If we're told to write to a structured log file, but it's not open,
dump the data
+ * to syslogFile (which is always open) instead. This can happen if
structured
* output is enabled after postmaster start and we've been unable to
open
- * csvlogFile. There are also race conditions during a parameter change
- * whereby backends might send us CSV output before we open csvlogFile
or
- * after we close it. Writing CSV-formatted output to the regular log
+ * logFile. There are also race conditions during a parameter change
+ * whereby backends might send us structured output before we open the
logFile or
+ * after we close it. Writing formatted output to the regular log
* file isn't great, but it beats dropping log output on the floor.
*
- * Think not to improve this by trying to open csvlogFile on-the-fly.
Any
+ * Think not to improve this by trying to open logFile on-the-fly. Any
* failure in that would lead to recursion.
*/
- logfile = (destination == LOG_DESTINATION_CSVLOG &&
- csvlogFile != NULL) ? csvlogFile : syslogFile;
+ if ((destination & LOG_DESTINATION_CSVLOG) && csvlogFile != NULL)
+ logfile = csvlogFile;
+ else if ((destination & LOG_DESTINATION_JSONLOG) && jsonlogFile != NULL)
+ logfile = jsonlogFile;
+ else
+ logfile = syslogFile;
rc = fwrite(buffer, 1, count, logfile);
@@ -1174,7 +1247,8 @@ pipeThread(void *arg)
if (Log_RotationSize > 0)
{
if (ftell(syslogFile) >= Log_RotationSize * 1024L ||
- (csvlogFile != NULL && ftell(csvlogFile) >=
Log_RotationSize * 1024L))
+ (csvlogFile != NULL && ftell(csvlogFile) >=
Log_RotationSize * 1024L) ||
+ (jsonlogFile != NULL && ftell(jsonlogFile) >=
Log_RotationSize * 1024L))
SetLatch(MyLatch);
}
LeaveCriticalSection(&sysloggerSection);
@@ -1247,6 +1321,7 @@ logfile_rotate(bool time_based_rotation, int
size_rotation_for)
{
char *filename;
char *csvfilename = NULL;
+ char *jsonfilename = NULL;
pg_time_t fntime;
FILE *fh;
@@ -1264,6 +1339,9 @@ logfile_rotate(bool time_based_rotation, int
size_rotation_for)
filename = logfile_getname(fntime, NULL);
if (Log_destination & LOG_DESTINATION_CSVLOG)
csvfilename = logfile_getname(fntime, ".csv");
+ if (Log_destination & LOG_DESTINATION_JSONLOG)
+ jsonfilename = logfile_getname(fntime, ".json");
+
/*
* Decide whether to overwrite or append. We can overwrite if (a)
@@ -1301,6 +1379,8 @@ logfile_rotate(bool time_based_rotation, int
size_rotation_for)
pfree(filename);
if (csvfilename)
pfree(csvfilename);
+ if (jsonfilename)
+ pfree(jsonfilename);
return;
}
@@ -1315,10 +1395,10 @@ logfile_rotate(bool time_based_rotation, int
size_rotation_for)
}
/*
- * Same as above, but for csv file. Note that if LOG_DESTINATION_CSVLOG
- * was just turned on, we might have to open csvlogFile here though it
was
+ * Same as above, but for a structured file. Note that if
LOG_DESTINATION_[STRUCTURED]LOG
+ * was just turned on, we might have to open logFile here though it was
* not open before. In such a case we'll append not overwrite (since
- * last_csv_file_name will be NULL); that is consistent with the normal
+ * last_*_file_name will be NULL); that is consistent with the normal
* rules since it's not a time-based rotation.
*/
if ((Log_destination & LOG_DESTINATION_CSVLOG) &&
@@ -1374,11 +1454,66 @@ logfile_rotate(bool time_based_rotation, int
size_rotation_for)
pfree(last_csv_file_name);
last_csv_file_name = NULL;
}
+ else if ((Log_destination & LOG_DESTINATION_JSONLOG) &&
+ (jsonlogFile == NULL ||
+ time_based_rotation || (size_rotation_for &
LOG_DESTINATION_JSONLOG)))
+ {
+ if (Log_truncate_on_rotation && time_based_rotation &&
+ last_json_file_name != NULL &&
+ strcmp(jsonfilename, last_json_file_name) != 0)
+ fh = logfile_open(jsonfilename, "w", true);
+ else
+ fh = logfile_open(jsonfilename, "a", true);
+
+ if (!fh)
+ {
+ /*
+ * ENFILE/EMFILE are not too surprising on a busy
system; just
+ * keep using the old file till we manage to get a new
one.
+ * Otherwise, assume something's wrong with
Log_directory and stop
+ * trying to create files.
+ */
+ if (errno != ENFILE && errno != EMFILE)
+ {
+ ereport(LOG,
+ (errmsg("disabling automatic
rotation (use SIGHUP to re-enable)")));
+ rotation_disabled = true;
+ }
+
+ if (filename)
+ pfree(filename);
+ if (jsonfilename)
+ pfree(jsonfilename);
+ return;
+ }
+
+ if (jsonlogFile != NULL)
+ fclose(jsonlogFile);
+ jsonlogFile = fh;
+
+ /* instead of pfree'ing filename, remember it for next time */
+ if (last_json_file_name != NULL)
+ pfree(last_json_file_name);
+ last_json_file_name = jsonfilename;
+ jsonfilename = NULL;
+ }
+ else if (!(Log_destination & LOG_DESTINATION_JSONLOG) &&
+ jsonlogFile != NULL)
+ {
+ /* JSONLOG was just turned off, so close the old file */
+ fclose(jsonlogFile);
+ jsonlogFile = NULL;
+ if (last_json_file_name != NULL)
+ pfree(last_json_file_name);
+ last_json_file_name = NULL;
+ }
if (filename)
pfree(filename);
if (csvfilename)
pfree(csvfilename);
+ if (jsonfilename)
+ pfree(jsonfilename);
update_metainfo_datafile();
@@ -1466,7 +1601,8 @@ update_metainfo_datafile(void)
mode_t oumask;
if (!(Log_destination & LOG_DESTINATION_STDERR) &&
- !(Log_destination & LOG_DESTINATION_CSVLOG))
+ !(Log_destination & LOG_DESTINATION_CSVLOG) &&
+ !(Log_destination & LOG_DESTINATION_JSONLOG))
{
if (unlink(LOG_METAINFO_DATAFILE) < 0 && errno != ENOENT)
ereport(LOG,
@@ -1524,6 +1660,18 @@ update_metainfo_datafile(void)
return;
}
}
+ if (last_json_file_name && (Log_destination & LOG_DESTINATION_JSONLOG))
+ {
+ if (fprintf(fh, "jsonlog %s\n", last_json_file_name) < 0)
+ {
+ ereport(LOG,
+ (errcode_for_file_access(),
+ errmsg("could not write file \"%s\":
%m",
+
LOG_METAINFO_DATAFILE_TMP)));
+ fclose(fh);
+ return;
+ }
+ }
fclose(fh);
if (rename(LOG_METAINFO_DATAFILE_TMP, LOG_METAINFO_DATAFILE) != 0)
diff --git a/src/backend/utils/adt/misc.c b/src/backend/utils/adt/misc.c
index 88faf4dfd7..4931859627 100644
--- a/src/backend/utils/adt/misc.c
+++ b/src/backend/utils/adt/misc.c
@@ -843,11 +843,12 @@ pg_current_logfile(PG_FUNCTION_ARGS)
{
logfmt = text_to_cstring(PG_GETARG_TEXT_PP(0));
- if (strcmp(logfmt, "stderr") != 0 && strcmp(logfmt, "csvlog")
!= 0)
+ if (strcmp(logfmt, "stderr") != 0 && strcmp(logfmt, "csvlog")
!= 0 &&
+ strcmp(logfmt, "jsonlog") != 0)
ereport(ERROR,
(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
errmsg("log format \"%s\" is not
supported", logfmt),
- errhint("The supported log formats are
\"stderr\" and \"csvlog\".")));
+ errhint("The supported log formats are
\"stderr\", \"csvlog\", and \"jsonlog\".")));
}
fd = AllocateFile(LOG_METAINFO_DATAFILE, "r");
diff --git a/src/backend/utils/error/Makefile b/src/backend/utils/error/Makefile
index ef770dd2f2..65ba61fb3c 100644
--- a/src/backend/utils/error/Makefile
+++ b/src/backend/utils/error/Makefile
@@ -15,6 +15,7 @@ include $(top_builddir)/src/Makefile.global
OBJS = \
assert.o \
csvlog.o \
- elog.o
+ elog.o \
+ jsonlog.o
include $(top_srcdir)/src/backend/common.mk
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 68fb167976..064fbf7e61 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -2922,6 +2922,30 @@ send_message_to_server_log(ErrorData *edata)
pfree(buf.data);
}
}
+ /* Write to JSON log if enabled */
+ else if (Log_destination & LOG_DESTINATION_JSONLOG)
+ {
+ if (redirection_done || MyBackendType == B_LOGGER)
+ {
+ /*
+ * send JSON data if it's safe to do so (syslogger
doesn't need the
+ * pipe). First get back the space in the message
buffer.
+ */
+ pfree(buf.data);
+ write_jsonlog(edata);
+ }
+ else
+ {
+ /*
+ * syslogger not up (yet), so just dump the message to
stderr,
+ * unless we already did so above.
+ */
+ if (!(Log_destination & LOG_DESTINATION_STDERR) &&
+ whereToSendOutput != DestDebug)
+ write_console(buf.data, buf.len);
+ pfree(buf.data);
+ }
+ }
else
{
pfree(buf.data);
@@ -2964,6 +2988,8 @@ write_pipe_chunks(char *data, int len, int dest)
p.proto.flags |= PIPE_PROTO_DEST_STDERR;
else if (dest == LOG_DESTINATION_CSVLOG)
p.proto.flags |= PIPE_PROTO_DEST_CSVLOG;
+ else if (dest == LOG_DESTINATION_JSONLOG)
+ p.proto.flags |= PIPE_PROTO_DEST_JSONLOG;
/* write all but the last chunk */
while (len > PIPE_MAX_PAYLOAD)
diff --git a/src/backend/utils/error/jsonlog.c
b/src/backend/utils/error/jsonlog.c
new file mode 100644
index 0000000000..2777124977
--- /dev/null
+++ b/src/backend/utils/error/jsonlog.c
@@ -0,0 +1,312 @@
+/*-------------------------------------------------------------------------
+ *
+ * jsonlog.c
+ * JSON logging
+ *
+ * Copyright (c) 2021, PostgreSQL Global Development Group
+ *
+ *
+ * IDENTIFICATION
+ * src/backend/utils/error/jsonlog.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/json.h"
+#include "utils/ps_status.h"
+
+/*
+ * appendJSONKeyValue
+ * Append to given StringInfo a comma followed by a JSON key and value.
+ * Both the key and value will be escaped as JSON string literals.
+ */
+static void
+appendJSONKeyValue(StringInfo buf, const char *key, const char *value)
+{
+ if (value == NULL)
+ return;
+ appendStringInfoChar(buf, ',');
+ escape_json(buf, key);
+ appendStringInfoChar(buf, ':');
+ escape_json(buf, value);
+}
+
+/*
+ * appendJSONKeyValueFmt
+ * Evaluate the fmt string and then invoke appendJSONKeyValue as the
+ * value of the JSON property. Both the key and value will be escaped by
+ * appendJSONKeyValue.
+ */
+static void
+appendJSONKeyValueFmt(StringInfo buf, const char *key, const char *fmt,...)
+{
+ int save_errno = errno;
+ size_t len = 128; /* initial assumption about
buffer size */
+ char *value;
+
+ for (;;)
+ {
+ va_list args;
+ size_t newlen;
+
+ /*
+ * Allocate result buffer. Note that in frontend this maps to
malloc
+ * with exit-on-error.
+ */
+ value = (char *) palloc(len);
+
+ /* Try to format the data. */
+ errno = save_errno;
+ va_start(args, fmt);
+ newlen = pvsnprintf(value, len, fmt, args);
+ va_end(args);
+
+ if (newlen < len)
+ break; /* success */
+
+ /* Release buffer and loop around to try again with larger len.
*/
+ pfree(value);
+ len = newlen;
+ }
+ appendJSONKeyValue(buf, key, value);
+ /* Clean up */
+ pfree(value);
+}
+
+/*
+ * appendJSONKeyValueAsInt
+ * Append to given StringInfo a comma followed by a JSON key and value with
+ * value being formatted as a signed integer (a JSON number).
+ */
+static void
+appendJSONKeyValueAsInt(StringInfo buf, const char *key, int value)
+{
+ appendStringInfoChar(buf, ',');
+ escape_json(buf, key);
+ appendStringInfoChar(buf, ':');
+ appendStringInfo(buf, "%d", value);
+}
+
+/*
+ * appendJSONKeyValueAsInt
+ * Append to given StringInfo a comma followed by a JSON key and value with
+ * value being formatted as an unsigned integer (a JSON number).
+ */
+static void
+appendJSONKeyValueAsUInt(StringInfo buf, const char *key, int value)
+{
+ appendStringInfoChar(buf, ',');
+ escape_json(buf, key);
+ appendStringInfoChar(buf, ':');
+ appendStringInfo(buf, "%u", value);
+}
+
+/*
+ * appendJSONKeyValueAsInt
+ * Append to given StringInfo a comma followed by a JSON key and value with
+ * value being formatted as a long (a JSON number).
+ */
+static void
+appendJSONKeyValueAsLong(StringInfo buf, const char *key, long value)
+{
+ appendStringInfoChar(buf, ',');
+ escape_json(buf, key);
+ appendStringInfoChar(buf, ':');
+ appendStringInfo(buf, "%ld", value);
+}
+
+/*
+ * Write logs in json format.
+ */
+void
+write_jsonlog(ErrorData *edata)
+{
+ StringInfoData buf;
+
+ /* static counter for line numbers */
+ static long log_line_number = 0;
+
+ /* Has the counter been reset in the current process? */
+ static int log_my_pid = 0;
+
+ if (log_my_pid != MyProcPid)
+ {
+ log_line_number = 0;
+ log_my_pid = MyProcPid;
+ formatted_start_time[0] = '\0';
+ }
+ log_line_number++;
+
+ initStringInfo(&buf);
+
+ /* Initialize string */
+ appendStringInfoChar(&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 jsonlog messages.
+ */
+ if (formatted_log_time[0] == '\0')
+ setup_formatted_log_time();
+
+ /* First property does not use appendJSONKeyValue as it does not have
comma prefix */
+ escape_json(&buf, "timestamp");
+ appendStringInfoChar(&buf, ':');
+ escape_json(&buf, formatted_log_time);
+
+ /* username */
+ if (MyProcPort)
+ appendJSONKeyValue(&buf, "user", MyProcPort->user_name);
+
+ /* database name */
+ if (MyProcPort)
+ appendJSONKeyValue(&buf, "dbname", MyProcPort->database_name);
+
+ /* 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)
+ appendJSONKeyValueAsInt(&buf, "leader_pid",
leader->pid);
+ }
+
+ /* Process ID */
+ if (MyProcPid != 0)
+ appendJSONKeyValueAsInt(&buf, "pid", MyProcPid);
+
+ /* Remote host and port */
+ if (MyProcPort && MyProcPort->remote_host)
+ {
+ appendJSONKeyValue(&buf, "remote_host",
MyProcPort->remote_host);
+ if (MyProcPort->remote_port && MyProcPort->remote_port[0] !=
'\0')
+ appendJSONKeyValue(&buf, "remote_port",
MyProcPort->remote_port);
+ }
+
+ /* Session id */
+ appendJSONKeyValueFmt(&buf, "session_id", "%lx.%x", (long) MyStartTime,
MyProcPid);
+
+ /* Line number */
+ appendJSONKeyValueAsLong(&buf, "line_num", log_line_number);
+
+ /* PS display */
+ if (MyProcPort)
+ {
+ StringInfoData msgbuf;
+ const char *psdisp;
+ int displen;
+
+ initStringInfo(&msgbuf);
+ psdisp = get_ps_display(&displen);
+ appendBinaryStringInfo(&msgbuf, psdisp, displen);
+ appendJSONKeyValue(&buf, "ps", msgbuf.data);
+
+ pfree(msgbuf.data);
+ }
+
+ /* session start timestamp */
+ if (formatted_start_time[0] == '\0')
+ setup_formatted_start_time();
+ appendJSONKeyValue(&buf, "session_start", formatted_start_time);
+
+ /* Virtual transaction id */
+ /* keep VXID format in sync with lockfuncs.c */
+ if (MyProc != NULL && MyProc->backendId != InvalidBackendId)
+ appendJSONKeyValueFmt(&buf, "vxid", "%d/%u", MyProc->backendId,
MyProc->lxid);
+
+ /* Transaction id */
+ appendJSONKeyValueFmt(&buf, "txid", "%u", GetTopTransactionIdIfAny());
+
+ /* Error severity */
+ if (edata->elevel)
+ appendJSONKeyValue(&buf, "error_severity", (char *)
error_severity(edata->elevel));
+
+ /* query id */
+ appendJSONKeyValueFmt(&buf, "query_id", "%lld", (long long)
pgstat_get_my_query_id());
+
+ /* SQL state code */
+ if (edata->sqlerrcode)
+ appendJSONKeyValue(&buf, "state_code",
unpack_sql_state(edata->sqlerrcode));
+
+ /* errdetail or error_detail log */
+ if (edata->detail_log)
+ appendJSONKeyValue(&buf, "detail", edata->detail_log);
+ else if (edata->detail)
+ appendJSONKeyValue(&buf, "detail", edata->detail);
+
+ /* errhint */
+ if (edata->hint)
+ appendJSONKeyValue(&buf, "hint", edata->hint);
+
+ /* Internal query */
+ if (edata->internalquery)
+ appendJSONKeyValue(&buf, "internal_query",
edata->internalquery);
+
+ /* If the internal query got printed, print internal pos, too */
+ if (edata->internalpos > 0 && edata->internalquery != NULL)
+ appendJSONKeyValueAsUInt(&buf, "internal_position",
edata->internalpos);
+
+ /* errcontext */
+ if (edata->context && !edata->hide_ctx)
+ appendJSONKeyValue(&buf, "context", edata->context);
+
+ /* 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)
+ {
+ appendJSONKeyValue(&buf, "statement", debug_query_string);
+ if (edata->cursorpos > 0)
+ appendJSONKeyValueAsInt(&buf, "cursor_position",
edata->cursorpos);
+ }
+
+ /* file error location */
+ if (Log_error_verbosity >= PGERROR_VERBOSE)
+ {
+ if (edata->funcname)
+ appendJSONKeyValue(&buf, "func_name", edata->funcname);
+ if (edata->filename)
+ {
+ appendJSONKeyValue(&buf, "file_name", edata->filename);
+ appendJSONKeyValueAsInt(&buf, "file_line_num",
edata->lineno);
+ }
+ }
+
+ /* Application name */
+ if (application_name && application_name[0] != '\0')
+ appendJSONKeyValue(&buf, "application_name", application_name);
+
+ /* backend type */
+ appendJSONKeyValue(&buf, "backend_type", get_backend_type_for_log());
+
+ /* Error message */
+ appendJSONKeyValue(&buf, "message", edata->message);
+
+ /* Finish string */
+ appendStringInfoChar(&buf, '}');
+ appendStringInfoChar(&buf, '\n');
+
+ write_syslogger(buf.data, buf.len, LOG_DESTINATION_JSONLOG);
+
+ pfree(buf.data);
+}
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index 23236fa4c3..e38a312b53 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -11702,6 +11702,8 @@ check_log_destination(char **newval, void **extra,
GucSource source)
newlogdest |= LOG_DESTINATION_STDERR;
else if (pg_strcasecmp(tok, "csvlog") == 0)
newlogdest |= LOG_DESTINATION_CSVLOG;
+ else if (pg_strcasecmp(tok, "jsonlog") == 0)
+ newlogdest |= LOG_DESTINATION_JSONLOG;
#ifdef HAVE_SYSLOG
else if (pg_strcasecmp(tok, "syslog") == 0)
newlogdest |= LOG_DESTINATION_SYSLOG;
diff --git a/src/bin/pg_ctl/t/004_logrotate.pl
b/src/bin/pg_ctl/t/004_logrotate.pl
index aa0d64a4f7..c6f03f1047 100644
--- a/src/bin/pg_ctl/t/004_logrotate.pl
+++ b/src/bin/pg_ctl/t/004_logrotate.pl
@@ -6,7 +6,7 @@ use warnings;
use PostgresNode;
use TestLib;
-use Test::More tests => 10;
+use Test::More tests => 15;
use Time::HiRes qw(usleep);
# Extract the file name of a $format from the contents of
@@ -63,7 +63,7 @@ $node->init();
$node->append_conf(
'postgresql.conf', qq(
logging_collector = on
-log_destination = 'stderr, csvlog'
+log_destination = 'stderr, csvlog, jsonlog'
# these ensure stability of test results:
log_rotation_age = 0
lc_messages = 'C'
@@ -94,11 +94,13 @@ note "current_logfiles = $current_logfiles";
like(
$current_logfiles,
qr|^stderr log/postgresql-.*log
-csvlog log/postgresql-.*csv$|,
+csvlog log/postgresql-.*csv
+jsonlog log/postgresql-.*json$|,
'current_logfiles is sane');
check_log_pattern('stderr', $current_logfiles, 'division by zero', $node);
check_log_pattern('csvlog', $current_logfiles, 'division by zero', $node);
+check_log_pattern('jsonlog', $current_logfiles, 'division by zero', $node);
# Sleep 2 seconds and ask for log rotation; this should result in
# output into a different log file name.
@@ -120,7 +122,8 @@ note "now current_logfiles = $new_current_logfiles";
like(
$new_current_logfiles,
qr|^stderr log/postgresql-.*log
-csvlog log/postgresql-.*csv$|,
+csvlog log/postgresql-.*csv
+jsonlog log/postgresql-.*json$|,
'new current_logfiles is sane');
# Verify that log output gets to this file, too
@@ -128,5 +131,6 @@ $node->psql('postgres', 'fee fi fo fum');
check_log_pattern('stderr', $new_current_logfiles, 'syntax error', $node);
check_log_pattern('csvlog', $new_current_logfiles, 'syntax error', $node);
+check_log_pattern('jsonlog', $new_current_logfiles, 'syntax error', $node);
$node->stop();
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index ef0e2a7746..c1544cab26 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -5926,7 +5926,8 @@ SELECT * FROM parent WHERE key = 2400;
<para>
<productname>PostgreSQL</productname> supports several methods
for logging server messages, including
- <systemitem>stderr</systemitem>, <systemitem>csvlog</systemitem> and
+ <systemitem>stderr</systemitem>, <systemitem>csvlog</systemitem>,
+ <systemitem>jsonlog</systemitem>, and
<systemitem>syslog</systemitem>. On Windows,
<systemitem>eventlog</systemitem> is also supported. Set this
parameter to a list of desired log destinations separated by
@@ -5944,6 +5945,14 @@ SELECT * FROM parent WHERE key = 2400;
<xref linkend="guc-logging-collector"/> must be enabled to generate
CSV-format log output.
</para>
+ <para>
+ If <systemitem>jsonlog</systemitem> is included in
<varname>log_destination</varname>,
+ log entries are output in <acronym>JSON</acronym> format, which is
convenient for
+ loading logs into programs.
+ See <xref linkend="runtime-config-logging-jsonlog"/> for details.
+ <xref linkend="guc-logging-collector"/> must be enabled to generate
+ CSV-format log output.
+ </para>
<para>
When either <systemitem>stderr</systemitem> or
<systemitem>csvlog</systemitem> are included, the file
@@ -5955,13 +5964,14 @@ SELECT * FROM parent WHERE key = 2400;
<programlisting>
stderr log/postgresql.log
csvlog log/postgresql.csv
+jsonlog log/postgresql.json
</programlisting>
<filename>current_logfiles</filename> is recreated when a new log file
is created as an effect of rotation, and
when <varname>log_destination</varname> is reloaded. It is removed
when
- neither <systemitem>stderr</systemitem>
- nor <systemitem>csvlog</systemitem> are included
+ none of <systemitem>stderr</systemitem>,
+ <systemitem>csvlog</systemitem>, <systemitem>jsonlog</systemitem> are
included
in <varname>log_destination</varname>, and when the logging collector
is
disabled.
</para>
@@ -6101,6 +6111,13 @@ local0.* /var/log/postgresql
(If <varname>log_filename</varname> ends in <literal>.log</literal>,
the suffix is
replaced instead.)
</para>
+ <para>
+ If JSON-format output is enabled in <varname>log_destination</varname>,
+ <literal>.json</literal> will be appended to the timestamped
+ log file name to create the file name for JSON-format output.
+ (If <varname>log_filename</varname> ends in <literal>.log</literal>,
the suffix is
+ replaced instead.)
+ </para>
<para>
This parameter can only be set in the
<filename>postgresql.conf</filename>
file or on the server command line.
@@ -7433,6 +7450,50 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH
csv;
</orderedlist>
</para>
</sect2>
+ <sect2 id="runtime-config-logging-jsonlog">
+ <title>Using JSON-Format Log Output</title>
+
+ <para>
+ Including <literal>jsonlog</literal> in the
<varname>log_destination</varname> list
+ provides a convenient way to import log files into many different
programs.
+ This option emits log lines in (<acronym>JSON</acronym>) format.
+ Each log line is serialized as a JSON object with the following fields:
+<programlisting>
+ {
+ "timestamp": time stamp with milliseconds (string),
+ "user": user name (string),
+ "dbname": database name (string),
+ "pid": process ID (number),
+ "remote_host": client host (string)
+ "remote_port": port number (string),
+ "session_id": session ID (string),
+ "line_num": per-session line number (number),
+ "ps": current ps display (string),
+ "session_start": session start time (string),
+ "vxid": virtual transaction ID (string),
+ "txid": regular transaction ID (string),
+ "error_severity": error severity (string),
+ "state_code": SQLSTATE code (string),
+ "detail": error message detail (string),
+ "hint": hint (string),
+ "internal_query": internal query that led to the error (string),
+ "internal_position": cursor index into internal query (number),
+ "context": error context (string),
+ "statement": client supplied query string (string),
+ "cursor_position": cursor index into query string (string),
+ "func_name": error location function name (string),
+ "file_name": error location file name (string),
+ "file_line_num": error location file line number (number),
+ "application_name": client application name (string),
+ "message": error message (string)
+ }
+</programlisting>
+ String fields with null values are excluded from output.
+ Additional fields may be added in the future. User applications that
process jsonlog
+ output should ignore unknown fields.
+ </para>
+
+ </sect2>
<sect2>
<title>Process Title</title>
--
2.33.0
signature.asc
Description: PGP signature
