Feedback-ID: i0fe9450f:Fastmail
Date: Mon, 11 Mar 2024 16:43:06 +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: <Ze62CoRj9g3c1e9N@paquier.xyz>
References: <CANiRfmsK36A0i8mnQtzaxhSm3CUCimPwJPp4WQNq53OdSNkgWg@mail.gmail.com>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="xVVuDcVp6c6zilfh"
Content-Disposition: inline
In-Reply-To: <CANiRfmsK36A0i8mnQtzaxhSm3CUCimPwJPp4WQNq53OdSNkgWg@mail.gmail.com>
Archived-At: <https://www.postgresql.org/message-id/Ze62CoRj9g3c1e9N%40paquier.xyz>
Precedence: bulk


--xVVuDcVp6c6zilfh
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable

On Sat, Mar 09, 2024 at 09:09:39PM +0530, Kambam Vinay wrote:
> We observed a slight lag in timestamp for a few logs from the emit_log_ho=
ok
> hook implementation when the log_line_prefix GUC has '%m'.
>=20
> 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()).
>=20
> Attached patch sets the saved_timeval_set to false before executing the
> emit_log_hook()

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

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

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

iQIzBAABCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAmXutgoACgkQnvQgOdby
QH3I9RAAqkX47mNCSyhl3RYYJFjq9Gr/qAJP22X6YMQFmF5hQNDyarmiIIeSsH7x
Fu+e18cJoeyMPbux666HudbTa2ibdQAtT3uhnSV+wK8OmKz+HFcxDGB+vwe6I1Nf
tifmUQFE6tTuF/A7B+OvIz01S4z2KAa+w+pclNq4pEllEcL00vZ1oYVMioknyKyJ
dDdK40meu0nwIvxHlS1+h88/oqo5EEczjXZTzslcWQLa9URLdhrGLQDRK3GQilUV
IixuxOigFmMwcmp9HqmCDXK3c58J2nv4b0vYYg8Y74lPf5HnvVfPlNkWK/DC/u7I
Fk7KrhsDiXaBWfsXt6TGi2hkQIG8Lmk8I3bcNgfRgFgrysjZKt8FJPbng7vo0w2Z
WsNeMxRlR2zME+Eq1q8t2TK/okroNaaiCkrjNUKY1PShV3/0KEZXG6KGvzXIqGcB
Kso2jxCNnc51IYR/QNwGIhhtxzrCB9Uy2AD74PESv9SNAbMKuQv8K2D4sctJtogn
UAG/7iqK8ehr1wo7xQvXtVs9Qco5EQRw1qoAYV8xW3sYtSQgNA5gjusQNJKi6Uar
/EPGo15oJGuZrtmi0FQY3PHPe4OqNSmNgVbQPuZUZGXJ7lfAtgRI67jvJeKt6kOz
EQ8rOCGHvQ7Zn3wKybh3XkoB0EbQCEntlSFqcOhgHv6rANTkdv4=
=myVd
-----END PGP SIGNATURE-----

--xVVuDcVp6c6zilfh--