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

diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 52bc01058c5ced617938355d44cdde514427dfae..605ff3b04535478e086e8cb8c9ddec011a92dcb0 100644 (file)
--- 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)));