Feedback-ID: i0fe9450f:Fastmail
Date: Mon, 18 Mar 2024 14:12:57 +0900
From: Michael Paquier <michael@paquier.xyz>
To: Kambam Vinay <vinaykambam@gmail.com>
Cc: pgsql-hackers@postgresql.org
Subject: Re: Fix for timestamp lag issue from emit_log_hook when GUC
 log_line_prefix has '%m'
Message-ID: <ZffNWb5Zm8WZwMLY@paquier.xyz>
References: <CANiRfmsK36A0i8mnQtzaxhSm3CUCimPwJPp4WQNq53OdSNkgWg@mail.gmail.com>
 <Ze62CoRj9g3c1e9N@paquier.xyz>
 <CANiRfmtBUuMLJ5pn3PsDeKZcEHaJ1mbm9Fb5-LHsBWzmd5m=Ag@mail.gmail.com>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="Zk0Pbwwpkf3gGOns"
Content-Disposition: inline
In-Reply-To: <CANiRfmtBUuMLJ5pn3PsDeKZcEHaJ1mbm9Fb5-LHsBWzmd5m=Ag@mail.gmail.com>
Archived-At: <https://www.postgresql.org/message-id/ZffNWb5Zm8WZwMLY%40paquier.xyz>
Precedence: bulk


--Zk0Pbwwpkf3gGOns
Content-Type: multipart/mixed; boundary="VT+EhD3VPy0xZONq"
Content-Disposition: inline


--VT+EhD3VPy0xZONq
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

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

--VT+EhD3VPy0xZONq
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
	filename="v2-0001-set-saved_timeval_set-to-false-before-executing-e.patch"
Content-Transfer-Encoding: quoted-printable

=46rom db20e006f16de889ceb884d63dd25828ec711185 Mon Sep 17 00:00:00 2001
=46rom: Michael Paquier <michael@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 =3D 0;	/* to detect actual r=
ecursion */
=20
 /*
  * 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 =3D false;
@@ -1678,6 +1678,14 @@ EmitErrorReport(void)
 	CHECK_STACK_DEPTH();
 	oldcontext =3D MemoryContextSwitchTo(edata->assoc_context);
=20
+	/*
+	 * 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 =3D false;
+	formatted_log_time[0] =3D '\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] =3D '\0';
 				(void) get_formatted_log_time();
=20
 				if (padding !=3D 0)
@@ -3151,9 +3157,6 @@ send_message_to_server_log(ErrorData *edata)
=20
 	initStringInfo(&buf);
=20
-	saved_timeval_set =3D false;
-	formatted_log_time[0] =3D '\0';
-
 	log_line_prefix(&buf, edata);
 	appendStringInfo(&buf, "%s:  ", _(error_severity(edata->elevel)));
=20
--=20
2.43.0


--VT+EhD3VPy0xZONq--

--Zk0Pbwwpkf3gGOns
Content-Type: application/pgp-signature; name="signature.asc"

-----BEGIN PGP SIGNATURE-----

iQIzBAABCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAmX3zVgACgkQnvQgOdby
QH3TIxAApbwWpKBirTyW2/JPsPmr7dr5M9hGHsCuHvpctO8SIa6c3S6IibBXzMB0
5IVqyQsmnDDqjMEmoNNhxkD+4IVWdqenJPMmX2KQD7D/ZsnIzF4wAsJx03yuIuvS
gIHjzNnsggYhFBiubIvyGavcQn/CH+EiwP/zEoaR7ELYwWm4+6tiV9AofSv+TLfI
YMg/COAdt4iwELyP+T3HGbFzQgyG8ncdTc6gJ6tDFsamlW1rcEOJl56OboTrIdn4
y3Mg6UThjU7JkVQJe7Ng/elmA1Qr2XJoQ1rwoFGpEjeEJqCRAoEF8qtDlgHG3HLq
5w76xEZ4R1vmkEHLynE2x1TyfX/TyhGXuS+vglSU6OU7tYeXRMwfyPmlcFaxhIiY
q4iV2hSEniafu4HThbTjAkDAVWbOGr+W1k7nMA9y32iRtzgy9l6afZrBNViAe4yB
5X+zvIrR6rlXO9EaWSUQfBJUZxhd77X2bsfYiOBaibvn4HI/0dbD+V5l0FL+Nnqf
8oHVzJuLFY7GSIuDjURXBQMx7kFGrwfXLDEXxQ7nNZsdT/7ljdRhsj1kwhzVsmDn
Dk9hPJrELnpQNEr/DhnugHv5h3Xox/gOrO1+N6+HWouSvz7pMRHQ57vSwK/u5rj6
1jxCfLF0b85SOBK4mB/2M8mpIlhevrVG7pefazYRFYoK6OcZorw=
=0KyX
-----END PGP SIGNATURE-----

--Zk0Pbwwpkf3gGOns--