On Fri, Oct 08, 2021 at 12:28:58PM +0900, Michael Paquier wrote: > 0001 and 0003 have been applied independently, attached is a rebased > version.
Attached are rebased versions of the patch set, where I have done a cleaner split: - 0001 includes all the refactoring of the routines from elog.c. - 0002 moves csv logging into its own file. - 0003 introduces the JSON log. 0001 and 0002, the refactoring bits, are in a rather committable shape, so I'd like to apply that as the last refactoring pieces I know of for this thread. 0003 still needs a closer lookup, and one part I do not like much in it is the split for [u]int and long values when it comes to key and values. -- Michael
From 74a4d36e5f6cac1318a14168321c34edcd7d9b86 Mon Sep 17 00:00:00 2001
From: Michael Paquier <mich...@paquier.xyz>
Date: Tue, 19 Oct 2021 16:25:45 +0900
Subject: [PATCH v6 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.33.0
From 17af8a58c8286c7af347a95329769dd7d6c805c0 Mon Sep 17 00:00:00 2001
From: Michael Paquier <mich...@paquier.xyz>
Date: Tue, 5 Oct 2021 15:22:24 +0900
Subject: [PATCH v6 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.33.0
From c3a46da88ed75090d8582961c9c05e1ca887af5a Mon Sep 17 00:00:00 2001
From: Michael Paquier <mich...@paquier.xyz>
Date: Tue, 5 Oct 2021 15:59:44 +0900
Subject: [PATCH v6 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 | 323 +++++++++++++++++++++++++++++
src/backend/utils/misc/guc.c | 2 +
src/bin/pg_ctl/t/004_logrotate.pl | 12 +-
doc/src/sgml/config.sgml | 67 +++++-
10 files changed, 514 insertions(+), 26 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..449d327268 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 csvlog */
+ 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..f92ee64a47
--- /dev/null
+++ b/src/backend/utils/error/jsonlog.c
@@ -0,0 +1,323 @@
+/*-------------------------------------------------------------------------
+ *
+ * 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,
+ const char *fmt,...) pg_attribute_printf(3, 4);
+
+/*
+ * 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;
+ 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;
+
+ 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
+ *
+ * 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.
+ */
+ /* 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);
+
+ /* 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 */
+ start_time = get_formatted_start_time();
+ appendJSONKeyValue(&buf, "session_start", 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 (check_log_of_query(edata))
+ {
+ 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');
+
+ /* 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 d2ce4a8450..0b79753ec3 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -11714,6 +11714,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 13e91f3bc9..5f05fd2bad 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 => 14;
use Time::HiRes qw(usleep);
# Extract the file name of a $format from the contents of
@@ -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'
@@ -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 0bcc6fd322..72a8204818 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
