On Sun, Mar 17, 2024 at 07:35:57PM +0530, Kambam Vinay wrote:
> Thanks Michael for the review. Agree with your comment on the patch.
> updated the patch with recommended change.

That should be fine.  I would suggest to document why the reset is
done at this location, aka this is to ensure that the same formatted
timestamp is used across the board, for all log destinations as well
as hook callers that rely on log_line_prefix.

While reviewing, I have noticed that a comment was not correct: JSON
logs also use the formatted timestamp via get_formatted_log_time().

I may be able to get this one committed just before the feature freeze
of v17, as timestamp consistency for hooks that call
log_status_format() is narrow.  For now, I have added an entry in the
CF app to keep track of it:
https://commitfest.postgresql.org/48/4901/
--
Michael
From db20e006f16de889ceb884d63dd25828ec711185 Mon Sep 17 00:00:00 2001
From: Michael Paquier <mich...@paquier.xyz>
Date: Mon, 18 Mar 2024 14:08:45 +0900
Subject: [PATCH v2] set saved_timeval_set to false before executing
 emit_log_hook()

---
 src/backend/utils/error/elog.c | 15 +++++++++------
 1 file changed, 9 insertions(+), 6 deletions(-)

diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 52bc01058c..ea96047352 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 the hook, as the latter may use
+	 * Log_line_prefix.
+	 */
+	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.
@@ -2948,8 +2956,6 @@ log_status_format(StringInfo buf, const char *format, ErrorData *edata)
 					appendStringInfo(buf, "%ld", log_line_number);
 				break;
 			case 'm':
-				/* force a log timestamp reset */
-				formatted_log_time[0] = '\0';
 				(void) get_formatted_log_time();
 
 				if (padding != 0)
@@ -3151,9 +3157,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)));
 
-- 
2.43.0

Attachment: signature.asc
Description: PGP signature

Reply via email to