Subject: Fix for timestamp lag issue from emit_log_hook when GUC log_line_prefix has '%m'

From: Kambam Vinay <[email-masked]>
Date: Sat, 9 Mar 2024 21:09:39 +0530

Hi,

We observed a slight lag in timestamp for a few logs from the emit_log_hook
hook implementation when the log_line_prefix GUC has '%m'.

Upon debugging, we found that the saved_timeval_set variable is set to
'true' in get_formatted_log_time() but is not reset to 'false' until the
next call to send_message_to_server_log(). Due to this, saved_timeval_set
will be true during the execution of hook emit_log_hook() which prefixes
the saved timestamp 'saved_timeval' from the previous log line (our hook
implementation calls log_line_prefix()).

Attached patch sets the saved_timeval_set to false before executing the
emit_log_hook()

Thanks,
Vinay

---

From: Michael Paquier <[email-masked]>
Date: Mon, 11 Mar 2024 16:43:06 +0900

> Attached patch sets the saved_timeval_set to false before executing the

Indeed.  If you rely on log_line_prefix() in your hook before the
server side elog, the saved timestamp would not match with what could
be computed in the follow-up send_message_to_server_log or
send_message_to_frontend.

Hmm.  Shouldn't we remove the forced reset of formatted_log_time for
the 'm' case in log_status_format() and remove the reset done at the
beginning of send_message_to_server_log()?  One problem with your
patch is that we would still finish with a different saved_timeval in
the hook and in send_message_to_server_log(), but we should do things
so as the timestamps are the same for the whole duration of
EmitErrorReport(), no?  It seems to me that a more correct solution
would be to reset saved_timeval_set and formatted_log_time[0] once
before the hook, at the beginning of EmitErrorReport().
--
Michael

---

From: Kambam Vinay <[email-masked]>
Date: Sun, 17 Mar 2024 19:35:57 +0530

Thanks Michael for the review. Agree with your comment on the patch.
updated the patch with recommended change.

Thanks,
Vinay

---

From: Michael Paquier <[email-masked]>
Date: Mon, 18 Mar 2024 14:12:57 +0900

> 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 <[email-masked]>
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

---

From: Michael Paquier <[email-masked]>
Date: Wed, 3 Apr 2024 15:13:13 +0900

> https://commitfest.postgresql.org/48/4901/

While looking again at that. there were two more comments that missed
a refresh about JSON in get_formatted_log_time() and
get_formatted_start_time().  It's been a few weeks since the last
update, but I'll be able to wrap that tomorrow, updating these
comments on the way.
--
Michael