On Wed, Sep 29, 2021 at 11:02:10AM +0900, Michael Paquier wrote: > This happens to not be a problem as only 32 bits are significant for > handles for both Win32 and Win64. This also means that we should be > able to remove the use for "long" in this code, making the routines > more symmetric. I have done more tests with Win32 and Win64, and > applied it. I don't have MinGW environments at hand, but looking at > the upstream code that should not matter. The buildfarm will let > us know soon enough if there is a problem thanks to the TAP tests of > pg_ctl.
So, I have been looking at the rest of the patch set for the last couple of days, and I think that I have spotted all the code paths that need to be smarter when it comes to multiple file-based log destinations. Attached is a new patch set: - 0001 does some refactoring of the file rotation in syslogger.c, that's the same patch as previously posted. - 0002 is more refactoring of elog.c, adding routines for the start timestamp, log timestamp, the backend type and an extra one to check if a query can be logged or not. - 0003 is a change to send_message_to_server_log() to be smarter regarding the fallback to stderr if a csvlog (or a jsonlog!) entry cannot be logged because the redirection is not ready yet. The code of HEAD processes first stderr, then csvlog, with csvlog moving back to stderr if not done yet. That's a bit strange, because for example on WIN32 we would lose any csvlog entry for a service. I propose here to do csvlog first, and fallback to stderr so as it gets done in one code path instead of two. I have spent quite a bit of time thinking about the best way to handle the case of multiple file log destinations here because we don't want to log multiple times to stderr if csvlog and jsonlog are both enabled. And I think that this is the simplest thing we could do. - 0004 moves the CSV-specific code into its own file. This include some refactoring of elog.c that should be moved to 0002, as this requires more routines of elog.c to be published: -- write_pipe_chunks() -- error_severity() - 0005 is the main meat, that introduces JSON as log_destination. This compiles and passes all my tests, but I have not really done an in-depth review of this code yet. 0002 and 0004 could be more polished and most of their pieces had better be squashed together. 0003, though, would improve the case of WIN32 where only csvlog is enabled so as log entries are properly redirected to the event logs if the redirection is not done yet. I'd like to move on with 0001 and 0003 as independent pieces. Sehrope, any thoughts? -- Michael
From 4641f8535c2be4b75285ac34d87e883bec250e48 Mon Sep 17 00:00:00 2001
From: Michael Paquier <mich...@paquier.xyz>
Date: Tue, 28 Sep 2021 11:48:18 +0900
Subject: [PATCH v4 1/5] Refactor per-destination file rotation in syslogger
---
src/backend/postmaster/syslogger.c | 242 ++++++++++++++---------------
1 file changed, 119 insertions(+), 123 deletions(-)
diff --git a/src/backend/postmaster/syslogger.c b/src/backend/postmaster/syslogger.c
index c5f9c5202d..4a019db7f4 100644
--- a/src/backend/postmaster/syslogger.c
+++ b/src/backend/postmaster/syslogger.c
@@ -87,7 +87,7 @@ static bool rotation_disabled = false;
static FILE *syslogFile = NULL;
static FILE *csvlogFile = NULL;
NON_EXEC_STATIC pg_time_t first_syslogger_file_time = 0;
-static char *last_file_name = NULL;
+static char *last_sys_file_name = NULL;
static char *last_csv_file_name = NULL;
/*
@@ -274,7 +274,7 @@ SysLoggerMain(int argc, char *argv[])
* time because passing down just the pg_time_t is a lot cheaper than
* passing a whole file path in the EXEC_BACKEND case.
*/
- last_file_name = logfile_getname(first_syslogger_file_time, NULL);
+ 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");
@@ -1241,16 +1241,118 @@ logfile_open(const char *filename, const char *mode, bool allow_errors)
return fh;
}
+/*
+ * Do logfile rotation for a single destination, as specified by target_dest.
+ * The information stored in *last_file_name and *logFile is updated on a
+ * successful file rotation.
+ *
+ * Returns false if the rotation has been stopped, and true to move on to
+ * the processing of other formats.
+ */
+static bool
+logfile_rotate_dest(bool time_based_rotation, int size_rotation_for,
+ pg_time_t fntime, int target_dest,
+ char **last_file_name, FILE **logFile)
+{
+ char *logFileExt;
+ char *filename;
+ FILE *fh;
+
+ /*
+ * If the target destination was just turned off, close the previous
+ * file and unregister its data. This cannot happen for stderr as
+ * syslogFile is assumed to be always opened even if
+ * LOG_DESTINATION_STDERR is disabled.
+ */
+ if ((Log_destination & target_dest) == 0 &&
+ target_dest != LOG_DESTINATION_STDERR)
+ {
+ if (*logFile != NULL)
+ fclose(*logFile);
+ *logFile = NULL;
+ if (*last_file_name != NULL)
+ pfree(*last_file_name);
+ *last_file_name = NULL;
+ return true;
+ }
+
+ /*
+ * Leave if it is not time for a rotation or if the target destination
+ * has no need to do a rotation.
+ */
+ if (!time_based_rotation &&
+ (size_rotation_for & target_dest) == 0)
+ {
+ return true;
+ }
+
+ /* file extension depends on the destination type */
+ if (target_dest == LOG_DESTINATION_STDERR)
+ logFileExt = NULL;
+ else if (target_dest == LOG_DESTINATION_CSVLOG)
+ logFileExt = ".csv";
+ else
+ {
+ /* cannot happen */
+ Assert(false);
+ }
+
+ /* build the new file name */
+ filename = logfile_getname(fntime, logFileExt);
+
+ /*
+ * Decide whether to overwrite or append. We can overwrite if (a)
+ * Log_truncate_on_rotation is set, (b) the rotation was triggered by
+ * elapsed time and not something else, and (c) the computed file name is
+ * different from what we were previously logging into.
+ */
+ if (Log_truncate_on_rotation && time_based_rotation &&
+ *last_file_name != NULL &&
+ strcmp(filename, *last_file_name) != 0)
+ fh = logfile_open(filename, "w", true);
+ else
+ fh = logfile_open(filename, "a", true);
+
+ if (!fh)
+ {
+ /*
+ * ENFILE/EMFILE are not too surprising on a busy system; just keep
+ * using the old file till we manage to get a new one. Otherwise,
+ * assume something's wrong with Log_directory and stop trying to
+ * create files.
+ */
+ if (errno != ENFILE && errno != EMFILE)
+ {
+ ereport(LOG,
+ (errmsg("disabling automatic rotation (use SIGHUP to re-enable)")));
+ rotation_disabled = true;
+ }
+
+ if (filename)
+ pfree(filename);
+ return false;
+ }
+
+ /* fill in the new information */
+ if (*logFile != NULL)
+ fclose(*logFile);
+ *logFile = fh;
+
+ /* instead of pfree'ing filename, remember it for next time */
+ if (*last_file_name != NULL)
+ pfree(*last_file_name);
+ *last_file_name = filename;
+
+ return true;
+}
+
/*
* perform logfile rotation
*/
static void
logfile_rotate(bool time_based_rotation, int size_rotation_for)
{
- char *filename;
- char *csvfilename = NULL;
pg_time_t fntime;
- FILE *fh;
rotation_requested = false;
@@ -1263,124 +1365,18 @@ logfile_rotate(bool time_based_rotation, int size_rotation_for)
fntime = next_rotation_time;
else
fntime = time(NULL);
- filename = logfile_getname(fntime, NULL);
- if (Log_destination & LOG_DESTINATION_CSVLOG)
- csvfilename = logfile_getname(fntime, ".csv");
- /*
- * Decide whether to overwrite or append. We can overwrite if (a)
- * Log_truncate_on_rotation is set, (b) the rotation was triggered by
- * elapsed time and not something else, and (c) the computed file name is
- * different from what we were previously logging into.
- *
- * Note: last_file_name should never be NULL here, but if it is, append.
- */
- if (time_based_rotation || (size_rotation_for & LOG_DESTINATION_STDERR))
- {
- if (Log_truncate_on_rotation && time_based_rotation &&
- last_file_name != NULL &&
- strcmp(filename, last_file_name) != 0)
- fh = logfile_open(filename, "w", true);
- else
- fh = logfile_open(filename, "a", true);
+ /* file rotation for stderr */
+ if (!logfile_rotate_dest(time_based_rotation, size_rotation_for, fntime,
+ LOG_DESTINATION_STDERR, &last_sys_file_name,
+ &syslogFile))
+ return;
- if (!fh)
- {
- /*
- * ENFILE/EMFILE are not too surprising on a busy system; just
- * keep using the old file till we manage to get a new one.
- * Otherwise, assume something's wrong with Log_directory and stop
- * trying to create files.
- */
- if (errno != ENFILE && errno != EMFILE)
- {
- ereport(LOG,
- (errmsg("disabling automatic rotation (use SIGHUP to re-enable)")));
- rotation_disabled = true;
- }
-
- if (filename)
- pfree(filename);
- if (csvfilename)
- pfree(csvfilename);
- return;
- }
-
- fclose(syslogFile);
- syslogFile = fh;
-
- /* instead of pfree'ing filename, remember it for next time */
- if (last_file_name != NULL)
- pfree(last_file_name);
- last_file_name = filename;
- filename = NULL;
- }
-
- /*
- * Same as above, but for csv file. Note that if LOG_DESTINATION_CSVLOG
- * was just turned on, we might have to open csvlogFile here though it was
- * not open before. In such a case we'll append not overwrite (since
- * last_csv_file_name will be NULL); that is consistent with the normal
- * rules since it's not a time-based rotation.
- */
- if ((Log_destination & LOG_DESTINATION_CSVLOG) &&
- (csvlogFile == NULL ||
- time_based_rotation || (size_rotation_for & LOG_DESTINATION_CSVLOG)))
- {
- if (Log_truncate_on_rotation && time_based_rotation &&
- last_csv_file_name != NULL &&
- strcmp(csvfilename, last_csv_file_name) != 0)
- fh = logfile_open(csvfilename, "w", true);
- else
- fh = logfile_open(csvfilename, "a", true);
-
- if (!fh)
- {
- /*
- * ENFILE/EMFILE are not too surprising on a busy system; just
- * keep using the old file till we manage to get a new one.
- * Otherwise, assume something's wrong with Log_directory and stop
- * trying to create files.
- */
- if (errno != ENFILE && errno != EMFILE)
- {
- ereport(LOG,
- (errmsg("disabling automatic rotation (use SIGHUP to re-enable)")));
- rotation_disabled = true;
- }
-
- if (filename)
- pfree(filename);
- if (csvfilename)
- pfree(csvfilename);
- return;
- }
-
- if (csvlogFile != NULL)
- fclose(csvlogFile);
- csvlogFile = fh;
-
- /* instead of pfree'ing filename, remember it for next time */
- if (last_csv_file_name != NULL)
- pfree(last_csv_file_name);
- last_csv_file_name = csvfilename;
- csvfilename = NULL;
- }
- else if (!(Log_destination & LOG_DESTINATION_CSVLOG) &&
- csvlogFile != NULL)
- {
- /* CSVLOG was just turned off, so close the old file */
- fclose(csvlogFile);
- csvlogFile = NULL;
- if (last_csv_file_name != NULL)
- pfree(last_csv_file_name);
- last_csv_file_name = NULL;
- }
-
- if (filename)
- pfree(filename);
- if (csvfilename)
- pfree(csvfilename);
+ /* file rotation for csvlog */
+ if (!logfile_rotate_dest(time_based_rotation, size_rotation_for, fntime,
+ LOG_DESTINATION_CSVLOG, &last_csv_file_name,
+ &csvlogFile))
+ return;
update_metainfo_datafile();
@@ -1501,9 +1497,9 @@ update_metainfo_datafile(void)
return;
}
- if (last_file_name && (Log_destination & LOG_DESTINATION_STDERR))
+ if (last_sys_file_name && (Log_destination & LOG_DESTINATION_STDERR))
{
- if (fprintf(fh, "stderr %s\n", last_file_name) < 0)
+ if (fprintf(fh, "stderr %s\n", last_sys_file_name) < 0)
{
ereport(LOG,
(errcode_for_file_access(),
--
2.33.0
From 83a5bd50da25d6a99e5804b0bd268b3a9e86644e Mon Sep 17 00:00:00 2001
From: Michael Paquier <mich...@paquier.xyz>
Date: Tue, 5 Oct 2021 11:19:46 +0900
Subject: [PATCH v4 2/5] 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
- log_timestamp
- decide if query can be logged
- backend type
This will be reused by jsonlog.
---
src/include/utils/elog.h | 4 +
src/backend/utils/error/elog.c | 141 +++++++++++++++++++++------------
2 files changed, 94 insertions(+), 51 deletions(-)
diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h
index f53607e12e..bc6f362b6a 100644
--- a/src/include/utils/elog.h
+++ b/src/include/utils/elog.h
@@ -441,6 +441,10 @@ extern bool syslog_split_messages;
extern void DebugFileOpen(void);
extern char *unpack_sql_state(int sql_state);
extern bool in_error_recursion_trouble(void);
+extern char *get_formatted_start_time(void);
+extern char *get_formatted_log_time(void);
+extern bool check_log_of_query(ErrorData *edata);
+extern const char *get_backend_type_for_log(void);
#ifdef HAVE_SYSLOG
extern void set_syslog_parameters(const char *ident, int facility);
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 2af87ee3bd..3d89937322 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -175,8 +175,6 @@ 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);
@@ -2289,14 +2287,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 +2325,25 @@ 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
+ * 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.
*/
-static void
-setup_formatted_start_time(void)
+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 +2352,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 +2525,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 +2613,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 +2657,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)
@@ -2763,6 +2820,8 @@ 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 +2844,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 +2904,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 +2956,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 +2990,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 */
@@ -3100,9 +3141,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: "));
--
2.33.0
From b3b57f3bc30cedd59b199c2fa0178d4f7cdd1703 Mon Sep 17 00:00:00 2001
From: Michael Paquier <mich...@paquier.xyz>
Date: Tue, 5 Oct 2021 14:24:59 +0900
Subject: [PATCH v4 3/5] Refactor fallback to stderr for some cases with csvlog
send_message_to_server_log() would force a redirection of a log entry to
stderr in some cases, like the syslogger not being available yet. If
this happens, csvlog falls back to stderr to log something. The code
was organized so as stderr was happening before csvlog, with csvlog
calling checking for the same conditions as the stderr code path for a
second time, with a log handling rather buggy for Windows.
Instead, move the csvlog handling to be before stderr, tracking down if
it is necessary to log something to stderr after. The reduces the
handling of stderr to a single code path, and fixes one issue with the
case of a Windows service, where stderr is not available, where we would
lose log entries that should have been redirected from csvlog to
stderr.
---
src/backend/utils/error/elog.c | 56 ++++++++++++++++------------------
1 file changed, 26 insertions(+), 30 deletions(-)
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 3d89937322..01a317ea18 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -3049,6 +3049,7 @@ static void
send_message_to_server_log(ErrorData *edata)
{
StringInfoData buf;
+ bool fallback_to_stderr = false;
initStringInfo(&buf);
@@ -3198,8 +3199,29 @@ send_message_to_server_log(ErrorData *edata)
}
#endif /* WIN32 */
- /* Write to stderr, if enabled */
- if ((Log_destination & LOG_DESTINATION_STDERR) || whereToSendOutput == DestDebug)
+ /* Write to CSV log, if enabled */
+ if ((Log_destination & LOG_DESTINATION_CSVLOG) != 0)
+ {
+ /*
+ * Send CSV 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_csvlog(edata);
+ }
+ else
+ fallback_to_stderr = true;
+ }
+
+ /*
+ * Write to stderr, if enabled or if required because of a previous
+ * limitation.
+ */
+ if ((Log_destination & LOG_DESTINATION_STDERR) ||
+ whereToSendOutput == DestDebug ||
+ fallback_to_stderr)
{
/*
* Use the chunking protocol if we know the syslogger should be
@@ -3228,34 +3250,8 @@ send_message_to_server_log(ErrorData *edata)
if (MyBackendType == B_LOGGER)
write_syslogger_file(buf.data, buf.len, LOG_DESTINATION_STDERR);
- /* Write to CSV log if enabled */
- if (Log_destination & LOG_DESTINATION_CSVLOG)
- {
- if (redirection_done || MyBackendType == B_LOGGER)
- {
- /*
- * send CSV data if it's safe to do so (syslogger doesn't need the
- * pipe). First get back the space in the message buffer.
- */
- pfree(buf.data);
- write_csvlog(edata);
- }
- else
- {
- /*
- * syslogger not up (yet), so just dump the message to stderr,
- * unless we already did so above.
- */
- if (!(Log_destination & LOG_DESTINATION_STDERR) &&
- whereToSendOutput != DestDebug)
- write_console(buf.data, buf.len);
- pfree(buf.data);
- }
- }
- else
- {
- pfree(buf.data);
- }
+ /* No more need of the message formatted for stderr */
+ pfree(buf.data);
}
/*
--
2.33.0
From 5d5eeed08377d5da0203b249b2c4042353207578 Mon Sep 17 00:00:00 2001
From: Michael Paquier <mich...@paquier.xyz>
Date: Tue, 5 Oct 2021 15:22:24 +0900
Subject: [PATCH v4 4/5] Refactor CSV-specific code into its own file
This requires more routines of elog.c to be published.
---
src/include/utils/elog.h | 4 +
src/backend/utils/error/Makefile | 1 +
src/backend/utils/error/csvlog.c | 268 +++++++++++++++++++++++++++++++
src/backend/utils/error/elog.c | 251 ++---------------------------
4 files changed, 284 insertions(+), 240 deletions(-)
create mode 100644 src/backend/utils/error/csvlog.c
diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h
index bc6f362b6a..ab08e7fac8 100644
--- a/src/include/utils/elog.h
+++ b/src/include/utils/elog.h
@@ -441,10 +441,14 @@ extern bool syslog_split_messages;
extern void DebugFileOpen(void);
extern char *unpack_sql_state(int sql_state);
extern bool in_error_recursion_trouble(void);
+extern void reset_formatted_start_time(void);
extern char *get_formatted_start_time(void);
extern char *get_formatted_log_time(void);
extern bool check_log_of_query(ErrorData *edata);
extern const char *get_backend_type_for_log(void);
+extern const char *error_severity(int elevel);
+extern void write_csvlog(ErrorData *edata);
+extern void write_pipe_chunks(char *data, int len, int dest);
#ifdef HAVE_SYSLOG
extern void set_syslog_parameters(const char *ident, int facility);
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 01a317ea18..f99a173e15 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -177,11 +177,8 @@ static void set_errdata_field(MemoryContextData *cxt, char **ptr, const char *st
static void write_console(const char *line, int len);
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);
@@ -2329,6 +2326,15 @@ get_formatted_log_time(void)
return formatted_log_time;
}
+/*
+ * reset_formatted_start_time -- reset the start timestamp
+ */
+void
+reset_formatted_start_time(void)
+{
+ formatted_start_time[0] = '\0';
+}
+
/*
* get_formatted_start_time -- compute and get the start timestamp.
*
@@ -2786,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.
- */
-static 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.
@@ -3274,7 +3045,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;
@@ -3510,7 +3281,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 77687eb0fa733cc6990265d1918b79a82a185e24 Mon Sep 17 00:00:00 2001
From: Michael Paquier <mich...@paquier.xyz>
Date: Tue, 5 Oct 2021 15:59:44 +0900
Subject: [PATCH v4 5/5] 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 ab08e7fac8..87b3398ca6 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);
@@ -448,6 +449,7 @@ extern bool check_log_of_query(ErrorData *edata);
extern const char *get_backend_type_for_log(void);
extern const char *error_severity(int elevel);
extern void write_csvlog(ErrorData *edata);
+extern void write_jsonlog(ErrorData *edata);
extern void write_pipe_chunks(char *data, int len, int dest);
#ifdef HAVE_SYSLOG
diff --git a/src/backend/postmaster/syslogger.c b/src/backend/postmaster/syslogger.c
index 4a019db7f4..9d5de35a44 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.
@@ -277,6 +279,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);
@@ -363,6 +367,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.
@@ -413,6 +425,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)
@@ -422,7 +440,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);
}
@@ -628,6 +646,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
@@ -725,6 +757,11 @@ SysLogger_Start(void)
fclose(csvlogFile);
csvlogFile = NULL;
}
+ if (jsonlogFile != NULL)
+ {
+ fclose(jsonlogFile);
+ jsonlogFile = NULL;
+ }
return (int) sysloggerPid;
}
@@ -801,6 +838,7 @@ syslogger_forkexec(void)
int ac = 0;
char filenobuf[32];
char csvfilenobuf[32];
+ char jsonfilenobuf[32];
av[ac++] = "postgres";
av[ac++] = "--forklog";
@@ -813,6 +851,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));
@@ -830,8 +871,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().
@@ -844,6 +885,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 */
@@ -892,7 +935,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 &&
@@ -914,6 +959,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 */
@@ -1093,19 +1140,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);
@@ -1176,7 +1228,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);
@@ -1291,6 +1344,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 */
@@ -1378,6 +1433,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();
@@ -1464,7 +1525,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,
@@ -1522,6 +1584,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 f99a173e15..c96bb3d527 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -2986,6 +2986,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.
@@ -3061,6 +3077,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 aa0d64a4f7..caa5740254 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
@@ -63,7 +63,7 @@ $node->init();
$node->append_conf(
'postgresql.conf', qq(
logging_collector = on
-log_destination = 'stderr, csvlog'
+log_destination = 'stderr, csvlog, jsonlog'
# these ensure stability of test results:
log_rotation_age = 0
lc_messages = 'C'
@@ -94,11 +94,13 @@ note "current_logfiles = $current_logfiles";
like(
$current_logfiles,
qr|^stderr log/postgresql-.*log
-csvlog log/postgresql-.*csv$|,
+csvlog log/postgresql-.*csv
+jsonlog log/postgresql-.*json$|,
'current_logfiles is sane');
check_log_pattern('stderr', $current_logfiles, 'division by zero', $node);
check_log_pattern('csvlog', $current_logfiles, 'division by zero', $node);
+check_log_pattern('jsonlog', $current_logfiles, 'division by zero', $node);
# Sleep 2 seconds and ask for log rotation; this should result in
# output into a different log file name.
@@ -120,7 +122,8 @@ note "now current_logfiles = $new_current_logfiles";
like(
$new_current_logfiles,
qr|^stderr log/postgresql-.*log
-csvlog log/postgresql-.*csv$|,
+csvlog log/postgresql-.*csv
+jsonlog log/postgresql-.*json$|,
'new current_logfiles is sane');
# Verify that log output gets to this file, too
@@ -128,5 +131,6 @@ $node->psql('postgres', 'fee fi fo fum');
check_log_pattern('stderr', $new_current_logfiles, 'syntax error', $node);
check_log_pattern('csvlog', $new_current_logfiles, 'syntax error', $node);
+check_log_pattern('jsonlog', $new_current_logfiles, 'syntax error', $node);
$node->stop();
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 0a8e35c59f..7723e11cf7 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
