From 2a217c371799ae3ecd8d32a137cea874fad7f5dc Mon Sep 17 00:00:00 2001 From: Michael Paquier Date: Thu, 4 Apr 2024 14:15:22 +0900 Subject: [PATCH] Coordinate emit_log_hook and all log destinations to share the same timeval This would cause the timestamp values used by emit_log_hook and all the other log destinations to differ, because the timestamps are reset before sending the logs to the server and after calling the hook. This change matters for emit_log_hook when generating log information with 'n' or 'm' in log_line_prefix through log_status_format(), or when doing direct calls to get_formatted_log_time() like in the JSON or CSV log formats. While on it, this commit fixes a couple of comments related to the formatted timestamps where the JSON was not mentioned. Oversight in dc686681e079, that I have noticed while reviewing this patch. Author: Kambam Vinay, Michael Paquier Discussion: https://postgr.es/m/CANiRfmsK36A0i8mnQtzaxhSm3CUCimPwJPp4WQNq53OdSNkgWg@mail.gmail.com --- src/backend/utils/error/elog.c | 17 +++++++++++------ 1 file changed, 11 insertions(+), 6 deletions(-) diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c index 52bc01058c5..605ff3b0453 100644 --- a/src/backend/utils/error/elog.c +++ b/src/backend/utils/error/elog.c @@ -154,7 +154,7 @@ static int recursion_depth = 0; /* to detect actual recursion */ /* * Saved timeval and buffers for formatted timestamps that might be used by - * both log_line_prefix and csv logs. + * log_line_prefix, csv logs and JSON logs. */ static struct timeval saved_timeval; static bool saved_timeval_set = false; @@ -1678,6 +1678,14 @@ EmitErrorReport(void) CHECK_STACK_DEPTH(); oldcontext = MemoryContextSwitchTo(edata->assoc_context); + /* + * Reset the formatted timestamp fields before emitting any logs. This + * includes all the log destinations and emit_log_hook, as the latter + * could use log_line_prefix or the formatted timestamps. + */ + saved_timeval_set = false; + formatted_log_time[0] = '\0'; + /* * Call hook before sending message to log. The hook function is allowed * to turn off edata->output_to_server, so we must recheck that afterward. @@ -2632,7 +2640,7 @@ get_formatted_log_time(void) /* * 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 - * nonempty or CSV mode can be selected. + * nonempty or CSV/JSON mode can be selected. */ pg_strftime(formatted_log_time, FORMATTED_TS_LEN, /* leave room for milliseconds... */ @@ -2673,7 +2681,7 @@ get_formatted_start_time(void) /* * 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 - * nonempty or CSV mode can be selected. + * nonempty or CSV/JSON mode can be selected. */ pg_strftime(formatted_start_time, FORMATTED_TS_LEN, "%Y-%m-%d %H:%M:%S %Z", @@ -3151,9 +3159,6 @@ send_message_to_server_log(ErrorData *edata) initStringInfo(&buf); - saved_timeval_set = false; - formatted_log_time[0] = '\0'; - log_line_prefix(&buf, edata); appendStringInfo(&buf, "%s: ", _(error_severity(edata->elevel)));