Subject: Re: Add jsonlog log_destination for JSON server logs

From: Andres Freund <[email-masked]>
Date: Sun, 2 Jan 2022 13:34:45 -0800

Hi,

On 2021-11-10 22:44:49 +0900, Michael Paquier wrote:
> Patch 0003 has been heavily reworked, and it would be good to have an
> extra pair of eyes on it.  So I have switched the CF entry as "Needs
> Review" and added my name to the list of authors (originally this
> stuff took code portions of own module, as well).

The tests don't seem to pass on windows:
https://cirrus-ci.com/task/5412456754315264?logs=test_bin#L47
https://api.cirrus-ci.com/v1/artifact/task/5412456754315264/tap/src/bin/pg_ctl/tmp_check/log/regress_log_004_logrotate

psql:<stdin>:1: ERROR:  division by zero
could not open "c:/cirrus/src/bin/pg_ctl/tmp_check/t_004_logrotate_primary_data/pgdata/current_logfiles": The system cannot find the file specified at t/004_logrotate.pl line 87.

Greetings,

Andres Freund

---

From: Michael Paquier <[email-masked]>
Date: Wed, 5 Jan 2022 16:32:46 +0900

> could not open "c:/cirrus/src/bin/pg_ctl/tmp_check/t_004_logrotate_primary_data/pgdata/current_logfiles": The system cannot find the file specified at t/004_logrotate.pl line 87.

This seems to point out that the syslogger is too slow to capture the
logrotate signal, and the patch set is introducing nothing new in
terms of infrastructure, just an extra value for log_destination.
This stuff passes here, and I am not spotting something amiss after an
extra close read.

Attached is an updated patch set that increases the test timeout (5min
-> 10min).  That should help, I assume.
--
Michael
From 33fbcbe4c8d4ac43a10d6f9362a961352a8df8ca Mon Sep 17 00:00:00 2001
From: Michael Paquier <[email-masked]>
Date: Tue, 19 Oct 2021 16:25:45 +0900
Subject: [PATCH v8 1/3] Some refactoring of elog-specific routines

This refactors out the following things in elog.c, for ease of use
across multiple log destinations:
- start_timestamp (including reset)
- log_timestamp
- decide if query can be logged
- backend type
- write using the elog piped protocol
- Error severity to string.

These will be reused by csvlog and jsonlog.
---
 src/include/utils/elog.h       |  12 +++
 src/backend/utils/error/elog.c | 159 +++++++++++++++++++++------------
 2 files changed, 114 insertions(+), 57 deletions(-)

diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h
index f53607e12e..731f3e3cd8 100644
--- a/src/include/utils/elog.h
+++ b/src/include/utils/elog.h
@@ -442,6 +442,18 @@ extern void DebugFileOpen(void);
 extern char *unpack_sql_state(int sql_state);
 extern bool in_error_recursion_trouble(void);
 
+/* Common functions shared across destinations */
+extern void reset_formatted_start_time(void);
+extern char *get_formatted_start_time(void);
+extern char *get_formatted_log_time(void);
+extern const char *get_backend_type_for_log(void);
+extern bool	check_log_of_query(ErrorData *edata);
+extern const char *error_severity(int elevel);
+extern void write_pipe_chunks(char *data, int len, int dest);
+
+/* Destination-specific functions */
+extern void write_csvlog(ErrorData *edata);
+
 #ifdef HAVE_SYSLOG
 extern void set_syslog_parameters(const char *ident, int facility);
 #endif
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index f33729513a..a162258bab 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -175,15 +175,10 @@ 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);

@@ -2289,14 +2284,23 @@ write_console(const char *line, int len)
 }
 
 /*
- * setup formatted_log_time, for consistent times between CSV and regular logs
+ * get_formatted_log_time -- compute and get the log timestamp.
+ *
+ * The timestamp is computed if not set yet, so as it is kept consistent
+ * among all the log destinations that require it to be consistent.  Note
+ * that the computed timestamp is returned in a static buffer, not
+ * palloc()'d.
  */
-static void
-setup_formatted_log_time(void)
+char *
+get_formatted_log_time(void)
 {
 	pg_time_t	stamp_time;
 	char		msbuf[13];
 
+	/* leave if already computed */
+	if (formatted_log_time[0] != '\0')
+		return formatted_log_time;
+
 	if (!saved_timeval_set)
 	{
 		gettimeofday(&saved_timeval, NULL);
@@ -2318,16 +2322,34 @@ setup_formatted_log_time(void)
 	/* 'paste' milliseconds into place... */
 	sprintf(msbuf, ".%03d", (int) (saved_timeval.tv_usec / 1000));
 	memcpy(formatted_log_time + 19, msbuf, 4);
+
+	return formatted_log_time;
 }
 
 /*
- * setup formatted_start_time
+ * reset_formatted_start_time -- reset the start timestamp
  */
-static void
-setup_formatted_start_time(void)
+void
+reset_formatted_start_time(void)
+{
+	formatted_start_time[0] = '\0';
+}
+
+/*
+ * get_formatted_start_time -- compute and get the start timestamp.
+ *
+ * The timestamp is computed if not set yet.  Note that the computed
+ * timestamp is returned in a static buffer, not palloc()'d.
+ */
+char *
+get_formatted_start_time(void)
 {
 	pg_time_t	stamp_time = (pg_time_t) MyStartTime;
 
+	/* leave if already computed */
+	if (formatted_start_time[0] != '\0')
+		return formatted_start_time;
+
 	/*
 	 * Note: we expect that guc.c will ensure that log_timezone is set up (at
 	 * least with a minimal GMT value) before Log_line_prefix can become
@@ -2336,6 +2358,49 @@ setup_formatted_start_time(void)
 	pg_strftime(formatted_start_time, FORMATTED_TS_LEN,
 				"%Y-%m-%d %H:%M:%S %Z",
 				pg_localtime(&stamp_time, log_timezone));
+
+	return formatted_start_time;
+}
+
+/*
+ * check_log_of_query -- check if a query can be logged
+ */
+bool
+check_log_of_query(ErrorData *edata)
+{
+	/* log required? */
+	if (!is_log_level_output(edata->elevel, log_min_error_statement))
+		return false;
+
+	/* query log wanted? */
+	if (edata->hide_stmt)
+		return false;
+
+	/* query string available? */
+	if (debug_query_string == NULL)
+		return false;
+
+	return true;
+}
+
+/*
+ * get_backend_type_for_log -- backend type for log entries
+ *
+ * Returns a pointer to a static buffer, not palloc()'d.
+ */
+const char *
+get_backend_type_for_log(void)
+{
+	const char   *backend_type_str;
+
+	if (MyProcPid == PostmasterPid)
+		backend_type_str = "postmaster";
+	else if (MyBackendType == B_BG_WORKER)
+		backend_type_str = MyBgworkerEntry->bgw_type;
+	else
+		backend_type_str = GetBackendTypeDesc(MyBackendType);
+
+	return backend_type_str;
 }
 
 /*
@@ -2466,14 +2531,7 @@ log_line_prefix(StringInfo buf, ErrorData *edata)
 				break;
 			case 'b':
 				{
-					const char *backend_type_str;
-
-					if (MyProcPid == PostmasterPid)
-						backend_type_str = "postmaster";
-					else if (MyBackendType == B_BG_WORKER)
-						backend_type_str = MyBgworkerEntry->bgw_type;
-					else
-						backend_type_str = GetBackendTypeDesc(MyBackendType);
+					const char *backend_type_str = get_backend_type_for_log();
 
 					if (padding != 0)
 						appendStringInfo(buf, "%*s", padding, backend_type_str);
@@ -2561,7 +2619,10 @@ log_line_prefix(StringInfo buf, ErrorData *edata)
 					appendStringInfo(buf, "%ld", log_line_number);
 				break;
 			case 'm':
-				setup_formatted_log_time();
+				/* force a log timestamp reset */
+				formatted_log_time[0] = '\0';
+				(void) get_formatted_log_time();
+
 				if (padding != 0)
 					appendStringInfo(buf, "%*s", padding, formatted_log_time);
 				else
@@ -2602,12 +2663,14 @@ log_line_prefix(StringInfo buf, ErrorData *edata)
 				}
 				break;
 			case 's':
-				if (formatted_start_time[0] == '\0')
-					setup_formatted_start_time();
-				if (padding != 0)
-					appendStringInfo(buf, "%*s", padding, formatted_start_time);
-				else
-					appendStringInfoString(buf, formatted_start_time);
+				{
+					char   *start_time = get_formatted_start_time();
+
+					if (padding != 0)
+						appendStringInfo(buf, "%*s", padding, start_time);
+					else
+						appendStringInfoString(buf, start_time);
+				}
 				break;
 			case 'i':
 				if (MyProcPort)
@@ -2758,11 +2821,13 @@ appendCSVLiteral(StringInfo buf, const char *data)
  * 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
+void
 write_csvlog(ErrorData *edata)
 {
 	StringInfoData buf;
 	bool		print_stmt = false;
+	char	   *start_time;
+	char	   *log_time;
 
 	/* static counter for line numbers */
 	static long log_line_number = 0;
@@ -2785,17 +2850,9 @@ write_csvlog(ErrorData *edata)
 
 	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);
+	/* timestamp with milliseconds */
+	log_time = get_formatted_log_time();
+	appendStringInfoString(&buf, log_time);
 	appendStringInfoChar(&buf, ',');
 
 	/* username */
@@ -2853,9 +2910,8 @@ write_csvlog(ErrorData *edata)
 	appendStringInfoChar(&buf, ',');
 
 	/* session start timestamp */
-	if (formatted_start_time[0] == '\0')
-		setup_formatted_start_time();
-	appendStringInfoString(&buf, formatted_start_time);
+	start_time = get_formatted_start_time();
+	appendStringInfoString(&buf, start_time);
 	appendStringInfoChar(&buf, ',');
 
 	/* Virtual transaction id */
@@ -2906,10 +2962,7 @@ write_csvlog(ErrorData *edata)
 	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;
+	print_stmt = check_log_of_query(edata);
 	if (print_stmt)
 		appendCSVLiteral(&buf, debug_query_string);
 	appendStringInfoChar(&buf, ',');
@@ -2943,13 +2996,7 @@ write_csvlog(ErrorData *edata)
 	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));
-
+	appendCSVLiteral(&buf, get_backend_type_for_log());
 	appendStringInfoChar(&buf, ',');
 
 	/* leader PID */
@@ -3101,9 +3148,7 @@ send_message_to_server_log(ErrorData *edata)
 	/*
 	 * If the user wants the query that generated this error logged, do it.
 	 */
-	if (is_log_level_output(edata->elevel, log_min_error_statement) &&
-		debug_query_string != NULL &&
-		!edata->hide_stmt)
+	if (check_log_of_query(edata))
 	{
 		log_line_prefix(&buf, edata);
 		appendStringInfoString(&buf, _("STATEMENT:  "));
@@ -3233,7 +3278,7 @@ send_message_to_server_log(ErrorData *edata)
  * warning from ignoring write()'s result, so do a little dance with casting
  * rc to void to shut up the compiler.
  */
-static void
+void
 write_pipe_chunks(char *data, int len, int dest)
 {
 	PipeProtoChunk p;
@@ -3469,7 +3514,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.34.1

From 85d9fbee22f56e342ffcf8082a320764b0ad1237 Mon Sep 17 00:00:00 2001
From: Michael Paquier <[email-masked]>
Date: Tue, 5 Oct 2021 15:22:24 +0900
Subject: [PATCH v8 2/3] Refactor CSV-specific code into its own file

---
 src/backend/utils/error/Makefile |   1 +
 src/backend/utils/error/csvlog.c | 268 +++++++++++++++++++++++++++++++
 src/backend/utils/error/elog.c   | 235 ---------------------------
 3 files changed, 269 insertions(+), 235 deletions(-)
 create mode 100644 src/backend/utils/error/csvlog.c

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..443a91e168
--- /dev/null
+++ b/src/backend/utils/error/csvlog.c
@@ -0,0 +1,268 @@
+/*-------------------------------------------------------------------------
+ *
+ * csvlog.c
+ *	  CSV logging
+ *
+ * Portions Copyright (c) 1996-2021, PostgreSQL Global Development Group
+ * Portions Copyright (c) 1994, Regents of the University of Californi
+ *
+ *
+ * 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.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, '"');
+}
+
+/*
+ * write_csvlog -- Generate and write CSV log entry
+ *
+ * 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;
+	char	   *start_time;
+	char	   *log_time;
+
+	/* 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;
+		reset_formatted_start_time();
+	}
+	log_line_number++;
+
+	initStringInfo(&buf);
+
+	/* timestamp with milliseconds */
+	log_time = get_formatted_log_time();
+	appendStringInfoString(&buf, 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 */
+	start_time = get_formatted_start_time();
+	appendStringInfoString(&buf, 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 */
+	print_stmt = check_log_of_query(edata);
+	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');
+
+	/* 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);
+}
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index a162258bab..4406d8deff 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -2792,241 +2792,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.
- */
-void
-write_csvlog(ErrorData *edata)
-{
-	StringInfoData buf;
-	bool		print_stmt = false;
-	char	   *start_time;
-	char	   *log_time;
-
-	/* 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 */
-	log_time = get_formatted_log_time();
-	appendStringInfoString(&buf, 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 */
-	start_time = get_formatted_start_time();
-	appendStringInfoString(&buf, 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 */
-	print_stmt = check_log_of_query(edata);
-	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');
-
-	/* 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.
-- 
2.34.1

From 7417ee1ac6e6ee4d95f9b2e5f0b411c94515a957 Mon Sep 17 00:00:00 2001
From: Michael Paquier <[email-masked]>
Date: Thu, 11 Nov 2021 09:02:33 +0900
Subject: [PATCH v8 3/3] JSON logging

---
 src/include/postmaster/syslogger.h            |   1 +
 src/include/utils/elog.h                      |   2 +
 src/backend/postmaster/syslogger.c            | 107 ++++++-
 src/backend/utils/adt/misc.c                  |   5 +-
 src/backend/utils/error/Makefile              |   3 +-
 src/backend/utils/error/elog.c                |  18 ++
 src/backend/utils/error/jsonlog.c             | 294 ++++++++++++++++++
 src/backend/utils/misc/guc.c                  |   4 +-
 src/backend/utils/misc/postgresql.conf.sample |  13 +-
 src/bin/pg_ctl/t/004_logrotate.pl             |  16 +-
 doc/src/sgml/config.sgml                      | 203 +++++++++++-
 11 files changed, 631 insertions(+), 35 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.h b/src/include/utils/elog.h
index 731f3e3cd8..a32c790421 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);
@@ -453,6 +454,7 @@ extern void write_pipe_chunks(char *data, int len, int dest);
 
 /* Destination-specific functions */
 extern void write_csvlog(ErrorData *edata);
+extern void write_jsonlog(ErrorData *edata);
 
 #ifdef HAVE_SYSLOG
 extern void set_syslog_parameters(const char *ident, int facility);
diff --git a/src/backend/postmaster/syslogger.c b/src/backend/postmaster/syslogger.c
index d1f56b95a4..0cf03bcdef 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_sys_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.
@@ -281,6 +283,8 @@ SysLoggerMain(int argc, char *argv[])
 	last_sys_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);
@@ -367,6 +371,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.
@@ -417,6 +429,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)
@@ -426,7 +444,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);
 		}
 
@@ -632,6 +650,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
@@ -729,6 +761,11 @@ SysLogger_Start(void)
 				fclose(csvlogFile);
 				csvlogFile = NULL;
 			}
+			if (jsonlogFile != NULL)
+			{
+				fclose(jsonlogFile);
+				jsonlogFile = NULL;
+			}
 			return (int) sysloggerPid;
 	}
 
@@ -805,6 +842,7 @@ syslogger_forkexec(void)
 	int			ac = 0;
 	char		filenobuf[32];
 	char		csvfilenobuf[32];
+	char		jsonfilenobuf[32];
 
 	av[ac++] = "postgres";
 	av[ac++] = "--forklog";
@@ -817,6 +855,9 @@ syslogger_forkexec(void)
 	snprintf(csvfilenobuf, sizeof(csvfilenobuf), "%d",
 			 syslogger_fdget(csvlogFile));
 	av[ac++] = csvfilenobuf;
+	snprintf(jsonfilenobuf, sizeof(jsonfilenobuf), "%d",
+			 syslogger_fdget(jsonlogFile));
+	av[ac++] = jsonfilenobuf;
 
 	av[ac] = NULL;
 	Assert(ac < lengthof(av));
@@ -834,8 +875,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().
@@ -848,6 +889,8 @@ syslogger_parseArgs(int argc, char *argv[])
 	syslogFile = syslogger_fdopen(fd);
 	fd = atoi(*argv++);
 	csvlogFile = syslogger_fdopen(fd);
+	fd = atoi(*argv++);
+	jsonlogFile = syslogger_fdopen(fd);
 }
 #endif							/* EXEC_BACKEND */
 
@@ -896,7 +939,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 &&
@@ -918,6 +963,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 */
@@ -1097,19 +1144,24 @@ 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
-	 * 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
-	 * file isn't great, but it beats dropping log output on the floor.
+	 * 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 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);
 
@@ -1180,7 +1232,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);
@@ -1292,6 +1345,8 @@ logfile_rotate_dest(bool time_based_rotation, int size_rotation_for,
 		logFileExt = NULL;
 	else if (target_dest == LOG_DESTINATION_CSVLOG)
 		logFileExt = ".csv";
+	else if (target_dest == LOG_DESTINATION_JSONLOG)
+		logFileExt = ".json";
 	else
 	{
 		/* cannot happen */
@@ -1379,6 +1434,12 @@ logfile_rotate(bool time_based_rotation, int size_rotation_for)
 							 &csvlogFile))
 		return;
 
+	/* file rotation for jsonlog */
+	if (!logfile_rotate_dest(time_based_rotation, size_rotation_for, fntime,
+							 LOG_DESTINATION_JSONLOG, &last_json_file_name,
+							 &jsonlogFile))
+		return;
+
 	update_metainfo_datafile();
 
 	set_next_rotation_time();
@@ -1465,7 +1526,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,
@@ -1523,6 +1585,19 @@ 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 4406d8deff..39467be917 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -2984,6 +2984,22 @@ send_message_to_server_log(ErrorData *edata)
 			fallback_to_stderr = true;
 	}
 
+	/* Write to JSON log, if enabled */
+	if ((Log_destination & LOG_DESTINATION_JSONLOG) != 0)
+	{
+		/*
+		 * Send JSON data if it's safe to do so (syslogger doesn't need the
+		 * pipe).  If this is not possible, fallback to an entry written
+		 * to stderr.
+		 */
+		if (redirection_done || MyBackendType == B_LOGGER)
+		{
+			write_jsonlog(edata);
+		}
+		else
+			fallback_to_stderr = true;
+	}
+
 	/*
 	 * Write to stderr, if enabled or if required because of a previous
 	 * limitation.
@@ -3059,6 +3075,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..f2101b59ff
--- /dev/null
+++ b/src/backend/utils/error/jsonlog.c
@@ -0,0 +1,294 @@
+/*-------------------------------------------------------------------------
+ *
+ * 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.h"
+#include "utils/guc.h"
+#include "utils/json.h"
+#include "utils/ps_status.h"
+
+static void appendJSONKeyValueFmt(StringInfo buf, const char *key,
+								  bool escape_key,
+								  const char *fmt,...) pg_attribute_printf(4, 5);
+
+/*
+ * appendJSONKeyValue
+ * Append to a StringInfo a comma followed by a JSON key and value.
+ * The key is always escaped. The value can be escaped optionally.
+ */
+static void
+appendJSONKeyValue(StringInfo buf, const char *key, const char *value,
+				   bool escape_value)
+{
+	Assert(key != NULL);
+
+	if (value == NULL)
+		return;
+
+	appendStringInfoChar(buf, ',');
+	escape_json(buf, key);
+	appendStringInfoChar(buf, ':');
+
+	if (escape_value)
+		escape_json(buf, value);
+	else
+		appendStringInfoString(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,
+					  bool escape_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 */
+		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, escape_key);
+
+	/* Clean up */
+	pfree(value);
+}
+
+/*
+ * Write logs in json format.
+ */
+void
+write_jsonlog(ErrorData *edata)
+{
+	StringInfoData	buf;
+	char	   *start_time;
+	char	   *log_time;
+
+	/* 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;
+
+	/*
+	 * 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;
+		reset_formatted_start_time();
+	}
+	log_line_number++;
+
+	initStringInfo(&buf);
+
+	/* Initialize string */
+	appendStringInfoChar(&buf, '{');
+
+	/* timestamp with milliseconds */
+	log_time = get_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, log_time);
+
+	/* username */
+	if (MyProcPort)
+		appendJSONKeyValue(&buf, "user", MyProcPort->user_name, true);
+
+	/* database name */
+	if (MyProcPort)
+		appendJSONKeyValue(&buf, "dbname", MyProcPort->database_name, true);
+
+	/* Process ID */
+	if (MyProcPid != 0)
+		appendJSONKeyValueFmt(&buf, "pid", false, "%d", MyProcPid);
+
+	/* Remote host and port */
+	if (MyProcPort && MyProcPort->remote_host)
+	{
+		appendJSONKeyValue(&buf, "remote_host", MyProcPort->remote_host, true);
+		if (MyProcPort->remote_port && MyProcPort->remote_port[0] != '\0')
+			appendJSONKeyValue(&buf, "remote_port", MyProcPort->remote_port, false);
+	}
+
+	/* Session id */
+	appendJSONKeyValueFmt(&buf, "session_id", true, "%lx.%x", (long) MyStartTime, MyProcPid);
+
+	/* Line number */
+	appendJSONKeyValueFmt(&buf, "line_num", false, "%ld", 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, true);
+
+		pfree(msgbuf.data);
+	}
+
+	/* session start timestamp */
+	start_time = get_formatted_start_time();
+	appendJSONKeyValue(&buf, "session_start", start_time, true);
+
+	/* Virtual transaction id */
+	/* keep VXID format in sync with lockfuncs.c */
+	if (MyProc != NULL && MyProc->backendId != InvalidBackendId)
+		appendJSONKeyValueFmt(&buf, "vxid", true, "%d/%u", MyProc->backendId, MyProc->lxid);
+
+	/* Transaction id */
+	appendJSONKeyValueFmt(&buf, "txid", false, "%u", GetTopTransactionIdIfAny());
+
+	/* Error severity */
+	if (edata->elevel)
+		appendJSONKeyValue(&buf, "error_severity",
+						   (char *) error_severity(edata->elevel), true);
+
+	/* SQL state code */
+	if (edata->sqlerrcode)
+		appendJSONKeyValue(&buf, "state_code",
+						   unpack_sql_state(edata->sqlerrcode), true);
+
+	/* errmessage */
+	appendJSONKeyValue(&buf, "message", edata->message, true);
+
+	/* errdetail or error_detail log */
+	if (edata->detail_log)
+		appendJSONKeyValue(&buf, "detail", edata->detail_log, true);
+	else
+		appendJSONKeyValue(&buf, "detail", edata->detail, true);
+
+	/* errhint */
+	if (edata->hint)
+		appendJSONKeyValue(&buf, "hint", edata->hint, true);
+
+	/* internal query */
+	if (edata->internalquery)
+		appendJSONKeyValue(&buf, "internal_query", edata->internalquery, true);
+
+	/* if printed internal query, print internal pos too */
+	if (edata->internalpos > 0 && edata->internalquery != NULL)
+		appendJSONKeyValueFmt(&buf, "internal_position", false, "%u",
+							  edata->internalpos);
+
+	/* errcontext */
+	if (edata->context && !edata->hide_ctx)
+		appendJSONKeyValue(&buf, "context", edata->context, true);
+
+	/* user query --- only reported if not disabled by the caller */
+	if (check_log_of_query(edata))
+	{
+		appendJSONKeyValue(&buf, "statement", debug_query_string, true);
+		if (edata->cursorpos > 0)
+			appendJSONKeyValueFmt(&buf, "cursor_position", false, "%d",
+								  edata->cursorpos);
+	}
+
+	/* file error location */
+	if (Log_error_verbosity >= PGERROR_VERBOSE)
+	{
+		if (edata->funcname)
+			appendJSONKeyValue(&buf, "func_name", edata->funcname, true);
+		if (edata->filename)
+		{
+			appendJSONKeyValue(&buf, "file_name", edata->filename, true);
+			appendJSONKeyValueFmt(&buf, "file_line_num", false, "%d",
+								  edata->lineno);
+		}
+	}
+
+	/* Application name */
+	if (application_name && application_name[0] != '\0')
+		appendJSONKeyValue(&buf, "application_name", application_name, true);
+
+	/* backend type */
+	appendJSONKeyValue(&buf, "backend_type", get_backend_type_for_log(), true);
+
+	/* 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)
+			appendJSONKeyValueFmt(&buf, "leader_pid", false, "%d", leader->pid);
+	}
+
+	/* query id */
+	appendJSONKeyValueFmt(&buf, "query_id", false, "%lld",
+						  (long long) pgstat_get_my_query_id());
+
+	/* Finish string */
+	appendStringInfoChar(&buf, '}');
+	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_JSONLOG);
+	else
+		write_pipe_chunks(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 f9504d3aec..2c70804fae 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -4264,7 +4264,7 @@ static struct config_string ConfigureNamesString[] =
 		{"log_destination", PGC_SIGHUP, LOGGING_WHERE,
 			gettext_noop("Sets the destination for server log output."),
 			gettext_noop("Valid values are combinations of \"stderr\", "
-						 "\"syslog\", \"csvlog\", and \"eventlog\", "
+						 "\"syslog\", \"csvlog\", \"jsonlog\" and \"eventlog\", "
 						 "depending on the platform."),
 			GUC_LIST_INPUT
 		},
@@ -11740,6 +11740,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/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index a1acd46b61..817d5f5324 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -432,14 +432,15 @@
 # - Where to Log -
 
 #log_destination = 'stderr'		# Valid values are combinations of
-					# stderr, csvlog, syslog, and eventlog,
-					# depending on platform.  csvlog
-					# requires logging_collector to be on.
+					# stderr, csvlog, jsonlog, syslog, and
+					# eventlog, depending on platform.
+					# csvlog and jsonlog require
+					# logging_collector to be on.
 
 # This is used when logging to stderr:
-#logging_collector = off		# Enable capturing of stderr and csvlog
-					# into log files. Required to be on for
-					# csvlogs.
+#logging_collector = off		# Enable capturing of stderr, jsonlog
+					# and csvlog into log files. Required
+					# to be on for csvlogs and jsonlogs.
 					# (change requires restart)
 
 # These are only used if logging_collector is on:
diff --git a/src/bin/pg_ctl/t/004_logrotate.pl b/src/bin/pg_ctl/t/004_logrotate.pl
index 3813a3b1fd..4b6ccd8e9b 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 PostgreSQL::Test::Cluster;
 use PostgreSQL::Test::Utils;
-use Test::More tests => 10;
+use Test::More tests => 14;
 use Time::HiRes qw(usleep);
 
 # Extract the file name of a $format from the contents of
@@ -39,7 +39,7 @@ sub check_log_pattern
 	my $node     = shift;
 	my $lfname   = fetch_file_name($logfiles, $format);
 
-	my $max_attempts = 180 * 10;
+	my $max_attempts = 360 * 10;
 
 	my $logcontents;
 	for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
@@ -65,7 +65,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'
@@ -78,7 +78,7 @@ $node->start();
 $node->psql('postgres', 'SELECT 1/0');
 
 # might need to retry if logging collector process is slow...
-my $max_attempts = 180 * 10;
+my $max_attempts = 360 * 10;
 
 my $current_logfiles;
 for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
@@ -96,11 +96,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.
@@ -122,7 +124,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
@@ -130,5 +133,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 afbb6c35e3..c29ced427c 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -5931,7 +5931,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
@@ -5949,6 +5950,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
+        JSON-format log output.
+       </para>
        <para>
         When either <systemitem>stderr</systemitem> or
         <systemitem>csvlog</systemitem> are included, the file
@@ -5960,13 +5969,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>
@@ -6106,6 +6116,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.
@@ -7467,6 +7484,186 @@ 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.
+     </para>
+
+     <para>
+      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>
+
+     <para>
+      Each log line is serialized as a JSON object as of the following
+      set of keys with their values.
+     </para>
+
+     <table>
+      <title>Keys and values of JSON log entries</title>
+      <tgroup cols="3">
+       <thead>
+        <row>
+         <entry>Key name</entry>
+         <entry>Type</entry>
+         <entry>Description</entry>
+        </row>
+       </thead>
+       <tbody>
+        <row>
+         <entry><literal>timestamp</literal></entry>
+         <entry>string</entry>
+         <entry>Time stamp with milliseconds</entry>
+        </row>
+        <row>
+         <entry><literal>user</literal></entry>
+         <entry>string</entry>
+         <entry>User name</entry>
+        </row>
+        <row>
+         <entry><literal>dbname</literal></entry>
+         <entry>string</entry>
+         <entry>Database name</entry>
+        </row>
+        <row>
+         <entry><literal>pid</literal></entry>
+         <entry>number</entry>
+         <entry>Process ID</entry>
+        </row>
+        <row>
+         <entry><literal>remote_host</literal></entry>
+         <entry>string</entry>
+         <entry>Client host</entry>
+        </row>
+        <row>
+         <entry><literal>remote_port</literal></entry>
+         <entry>number</entry>
+         <entry>Client port</entry>
+        </row>
+        <row>
+         <entry><literal>session_id</literal></entry>
+         <entry>string</entry>
+         <entry>Session ID</entry>
+        </row>
+        <row>
+         <entry><literal>line_num</literal></entry>
+         <entry>number</entry>
+         <entry>Per-session line number</entry>
+        </row>
+        <row>
+         <entry><literal>ps</literal></entry>
+         <entry>string</entry>
+         <entry>Current ps display</entry>
+        </row>
+        <row>
+         <entry><literal>session_start</literal></entry>
+         <entry>string</entry>
+         <entry>Session start time</entry>
+        </row>
+        <row>
+         <entry><literal>vxid</literal></entry>
+         <entry>string</entry>
+         <entry>Virtual transaction ID</entry>
+        </row>
+        <row>
+         <entry><literal>txid</literal></entry>
+         <entry>string</entry>
+         <entry>Regular transaction ID</entry>
+        </row>
+        <row>
+         <entry><literal>error_severity</literal></entry>
+         <entry>string</entry>
+         <entry>Error severity</entry>
+        </row>
+        <row>
+         <entry><literal>state_code</literal></entry>
+         <entry>string</entry>
+         <entry>SQLSTATE code</entry>
+        </row>
+        <row>
+         <entry><literal>message</literal></entry>
+         <entry>string</entry>
+         <entry>Error message</entry>
+        </row>
+        <row>
+         <entry><literal>detail</literal></entry>
+         <entry>string</entry>
+         <entry>Error message detail</entry>
+        </row>
+        <row>
+         <entry><literal>hint</literal></entry>
+         <entry>string</entry>
+         <entry>Error message hint</entry>
+        </row>
+        <row>
+         <entry><literal>internal_query</literal></entry>
+         <entry>string</entry>
+         <entry>Internal query that led to the error</entry>
+        </row>
+        <row>
+         <entry><literal>internal_position</literal></entry>
+         <entry>number</entry>
+         <entry>Cursor index into internal query</entry>
+        </row>
+        <row>
+         <entry><literal>context</literal></entry>
+         <entry>string</entry>
+         <entry>Error context</entry>
+        </row>
+        <row>
+         <entry><literal>statement</literal></entry>
+         <entry>string</entry>
+         <entry>Client-supplied query string</entry>
+        </row>
+        <row>
+         <entry><literal>cursor_position</literal></entry>
+         <entry>string</entry>
+         <entry>Cursor index into query string</entry>
+        </row>
+        <row>
+         <entry><literal>func_name</literal></entry>
+         <entry>string</entry>
+         <entry>Error location function name</entry>
+        </row>
+        <row>
+         <entry><literal>file_name</literal></entry>
+         <entry>string</entry>
+         <entry>File name of error location</entry>
+        </row>
+        <row>
+         <entry><literal>file_line_num</literal></entry>
+         <entry>number</entry>
+         <entry>File line number of the error location</entry>
+        </row>
+        <row>
+         <entry><literal>application_name</literal></entry>
+         <entry>string</entry>
+         <entry>Client application name</entry>
+        </row>
+        <row>
+         <entry><literal>backend_type</literal></entry>
+         <entry>string</entry>
+         <entry>Type of backend</entry>
+        </row>
+        <row>
+         <entry><literal>leader_pid</literal></entry>
+         <entry>number</entry>
+         <entry>Process ID of leader for active parallel workers</entry>
+        </row>
+        <row>
+         <entry><literal>query_id</literal></entry>
+         <entry>number</entry>
+         <entry>Query ID</entry>
+        </row>
+       </tbody>
+      </tgroup>
+     </table>
+    </sect2>
 
    <sect2>
     <title>Process Title</title>
-- 
2.34.1

---

From: Andrew Dunstan <[email-masked]>
Date: Thu, 6 Jan 2022 13:06:03 -0500

> -> 10min).  That should help, I assume.

ITYM 3 min -> 6  min. But in any case, is that really going to solve
this? The file should exist, even if its contents are not up to date, AIUI.

cheers

andrew

--
Andrew Dunstan
EDB: https://www.enterprisedb.com

---

From: Andrew Dunstan <[email-masked]>
Date: Thu, 6 Jan 2022 18:28:26 -0500

> this? The file should exist, even if its contents are not up to date, AIUI.

I have tested on an msys2 setup with your v8 patches and I am getting this:

#   Failed test 'current_logfiles is sane'
#   at t/004_logrotate.pl line 96.
#                   'stderr log/postgresql-2022-01-06_222419.log
# csvlog log/postgresql-2022-01-06_222419.csv
# '
#     doesn't match '(?^:^stderr log/postgresql-.*log
# csvlog log/postgresql-.*csv
# jsonlog log/postgresql-.*json$)'

#   Failed test 'found expected log file content for stderr'
#   at t/004_logrotate.pl line 103.
#                   ''
#     doesn't match '(?^:division by zero)'

#   Failed test 'found expected log file content for jsonlog'
#   at t/004_logrotate.pl line 105.
#                   undef
#     doesn't match '(?^:division by zero)'

#   Failed test 'pg_current_logfile() gives correct answer with jsonlog'
#   at t/004_logrotate.pl line 105.
#          got: ''
#     expected: undef
# Looks like you failed 4 tests of 14.
[22:37:31] t/004_logrotate.pl ...
Dubious, test returned 4 (wstat 1024, 0x400)
Failed 4/14 subtests
[22:37:31]

cheers

andrew

---

From: Michael Paquier <[email-masked]>
Date: Fri, 7 Jan 2022 15:49:47 +0900

> # csvlog log/postgresql-2022-01-06_222419.csv

Yes, I was waiting for the latest results, but that did not help at
all.  Something is wrong with the patch, I am not sure what yet, but
that seems like a mistake in the backend part of it rather than the
tests.  I have switched the CF entry as waiting on author until this
is addressed.
--
Michael

---

From: Michael Paquier <[email-masked]>
Date: Mon, 10 Jan 2022 21:48:31 +0900

> tests.  I have switched the CF entry as waiting on author until this

The issue comes from an incorrect change in syslogger_parseArgs()
where I missed that the incrementation of argv by 3 has no need to be
changed.  A build with -DEXEC_BACKEND is enough to show the failure,
which caused a crash when starting up the syslogger because of a NULL
pointer dereference.  The attached v9 should be enough to switch the
CF bot to green.
--
Michael
From 6ab52532b232bc3314cef5c9c4ac38110957ab34 Mon Sep 17 00:00:00 2001
From: Michael Paquier <[email-masked]>
Date: Tue, 19 Oct 2021 16:25:45 +0900
Subject: [PATCH v9 1/3] Some refactoring of elog-specific routines

index 8df2799dc2..f37956f100 100644
 
index 2f2c3ba41b..4ccad9bac1 100644

 /*

 /*

 /*
 
 					if (padding != 0)

 	initStringInfo(&buf);
 
-	/*
 
 	/* username */

 
 
 	/* backend type */
 
 	/* leader PID */

From 6bd32c8a49fd4b6a1b08b39593c1e610c711f761 Mon Sep 17 00:00:00 2001
From: Michael Paquier <[email-masked]>
Date: Tue, 5 Oct 2021 15:22:24 +0900
Subject: [PATCH v9 2/3] Refactor CSV-specific code into its own file

---

 OBJS = \
 	assert.o \
+	csvlog.o \
 	elog.o
 
index 4ccad9bac1..511b43e4ac 100644
 
-/*

From 077656335da1aaf12b543f5d05c493804adfa4d5 Mon Sep 17 00:00:00 2001
From: Michael Paquier <[email-masked]>
Date: Mon, 10 Jan 2022 21:44:53 +0900
Subject: [PATCH v9 3/3] JSON logging

---
 src/backend/postmaster/syslogger.c            | 105 ++++++-
 11 files changed, 630 insertions(+), 34 deletions(-)

index 2df68a196e..1ca326e52e 100644
 
 /* GUC options */
index f37956f100..77c5a6b9a3 100644

 
 #ifdef HAVE_SYSLOG
index 2256f072aa..eb53260943 100644
 
 /*

+			/*
 
 		if (rotation_requested)

+	/*

 	av[ac++] = "postgres";
 	av[ac++] = "--forklog";
 
 	av[ac] = NULL;
 	Assert(ac < lengthof(av));
@@ -834,7 +875,7 @@ syslogger_parseArgs(int argc, char *argv[])
 {
 	int			fd;
 
-	Assert(argc == 5);
+	Assert(argc == 6);
 	argv += 3;
 
 	/*

 
 	/*

 

 
index fe4f180b6f..b3e1453bed 100644

 
index 511b43e4ac..680497de46 100644

index 6fc5cbc09a..b651429ed6 100644

 
index e04331bfef..c0194359b4 100644

 
 
 	my $logcontents;

 my $current_logfiles;

 

 $node->stop();

    <sect2>