On Sun, Jan 02, 2022 at 01:34:45PM -0800, Andres Freund wrote: > 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.
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 <mich...@paquier.xyz>
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 <mich...@paquier.xyz>
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 <mich...@paquier.xyz>
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
signature.asc
Description: PGP signature
