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

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_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()

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

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

On Mon, Mar 18, 2024 at 02:12:57PM +0900, Michael Paquier wrote:
> 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/

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

On Wed, Apr 03, 2024 at 03:13:13PM +0900, Michael Paquier wrote:
> 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.

And done with 2a217c371799, before the feature freeze.
--
Michael