Re: Custom timestamp format in logs

Hi all,

This week, we heard about a user willing to use a custom timestamp
format across a set of services to improve the debugability of the
whole set, Postgres being one of them. Unfortunately datestyle does
not take into account the logs. Would it be worth adding a new GUC
able to control the timestamp format in the logs?

We could still redirect the logs with syslog and have a custom
timestamp format there, but in the case of this particular user syslog
was a no-go. Looking at the code, timestamp format is now hardcoded in
setup_formatted_log_time and setup_formatted_start_time when calling
pg_strftime @ elog.c, so it doesn't seem to be much complicated to do.

Opinions? This thread is here for that.
Regards,
--
Michael

On Sat, Dec 13, 2014 at 3:50 PM, Michael Paquier <michael(dot)paquier(at)gmail(dot)com>
wrote:
>
> Hi all,
>
> This week, we heard about a user willing to use a custom timestamp
> format across a set of services to improve the debugability of the
> whole set, Postgres being one of them. Unfortunately datestyle does
> not take into account the logs. Would it be worth adding a new GUC
> able to control the timestamp format in the logs?
>
> We could still redirect the logs with syslog and have a custom
> timestamp format there, but in the case of this particular user syslog
> was a no-go. Looking at the code, timestamp format is now hardcoded in
> setup_formatted_log_time and setup_formatted_start_time when calling
> pg_strftime @ elog.c, so it doesn't seem to be much complicated to do.
>
> Opinions? This thread is here for that.
>

A separate GUC seems kind of weird. Wouldn't it be better with something
like %(format)t or such in the log_line_prefix itself in that case? That
could also be expanded to other parameters, should we need them?

--
Magnus Hagander
Me: http://www.hagander.net/
Work: http://www.redpill-linpro.com/

Magnus Hagander <magnus(at)hagander(dot)net> writes:
> On Sat, Dec 13, 2014 at 3:50 PM, Michael Paquier <michael(dot)paquier(at)gmail(dot)com>
> wrote:
>> This week, we heard about a user willing to use a custom timestamp
>> format across a set of services to improve the debugability of the
>> whole set, Postgres being one of them. Unfortunately datestyle does
>> not take into account the logs. Would it be worth adding a new GUC
>> able to control the timestamp format in the logs?

> A separate GUC seems kind of weird. Wouldn't it be better with something
> like %(format)t or such in the log_line_prefix itself in that case? That
> could also be expanded to other parameters, should we need them?

TBH, my answer to the rhetorical question is "no". There is nothing
weird about the timestamps %t emits now, and no reason why they should
need to be configurable, except that somebody thinks it's easier to
lobby us to complicate our software than to fix whatever they have that
can't consume standard timestamp format.

regards, tom lane

Tom Lane wrote:
> Magnus Hagander <magnus(at)hagander(dot)net> writes:
> > On Sat, Dec 13, 2014 at 3:50 PM, Michael Paquier <michael(dot)paquier(at)gmail(dot)com>
> > wrote:
> >> This week, we heard about a user willing to use a custom timestamp
> >> format across a set of services to improve the debugability of the
> >> whole set, Postgres being one of them. Unfortunately datestyle does
> >> not take into account the logs. Would it be worth adding a new GUC
> >> able to control the timestamp format in the logs?
>
> > A separate GUC seems kind of weird. Wouldn't it be better with something
> > like %(format)t or such in the log_line_prefix itself in that case? That
> > could also be expanded to other parameters, should we need them?
>
> TBH, my answer to the rhetorical question is "no". There is nothing
> weird about the timestamps %t emits now, and no reason why they should
> need to be configurable, except that somebody thinks it's easier to
> lobby us to complicate our software than to fix whatever they have that
> can't consume standard timestamp format.

I imagine pgBadger/pgFouine wouldn't be happy with the timestamp being
infinitely configurable.

--
Álvaro Herrera http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Alvaro Herrera <alvherre(at)2ndquadrant(dot)com> writes:
> Tom Lane wrote:
>> TBH, my answer to the rhetorical question is "no". There is nothing
>> weird about the timestamps %t emits now, and no reason why they should
>> need to be configurable, except that somebody thinks it's easier to
>> lobby us to complicate our software than to fix whatever they have that
>> can't consume standard timestamp format.

> I imagine pgBadger/pgFouine wouldn't be happy with the timestamp being
> infinitely configurable.

Yeah, if the repercussions were confined to the server code that would be
one thing, but there are a number of external tools that would be affected
as well. The "complication" cost has to be thought about that way rather
than evaluated in isolation.

You could argue that pgBadger et al could just document that they don't
support nonstandard timestamp formats ... but then it's really unclear why
we're shifting the complexity burden in this direction rather than asking
why the one proprietary application that wants the other thing can't cope
with the existing format choice.

regards, tom lane

On Mon, Dec 15, 2014 at 1:36 AM, Magnus Hagander <magnus(at)hagander(dot)net> wrote:
> On Sat, Dec 13, 2014 at 3:50 PM, Michael Paquier <michael(dot)paquier(at)gmail(dot)com>
> wrote:
>>
>> Hi all,
>>
>> This week, we heard about a user willing to use a custom timestamp
>> format across a set of services to improve the debugability of the
>> whole set, Postgres being one of them. Unfortunately datestyle does
>> not take into account the logs. Would it be worth adding a new GUC
>> able to control the timestamp format in the logs?
>>
>> We could still redirect the logs with syslog and have a custom
>> timestamp format there, but in the case of this particular user syslog
>> was a no-go. Looking at the code, timestamp format is now hardcoded in
>> setup_formatted_log_time and setup_formatted_start_time when calling
>> pg_strftime @ elog.c, so it doesn't seem to be much complicated to do.
>>
>> Opinions? This thread is here for that.
>
>
> A separate GUC seems kind of weird.
Check.

> Wouldn't it be better with something like %(format)t or such in the log_line_prefix itself in that case?
> That could also be expanded to other parameters, should we need them?
Possible. I am not sure if we will be able to have a new parameter in
log_line_prefix as modulable as timestamps for formatting though.
--
Michael

On Mon, Dec 15, 2014 at 3:16 AM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> You could argue that pgBadger et al could just document that they don't
> support nonstandard timestamp formats ... but then it's really unclear why
> we're shifting the complexity burden in this direction rather than asking
> why the one proprietary application that wants the other thing can't cope
> with the existing format choice.
Well, the opposite side can argue exactly the contrary with the user
hat: why doesn't Postgres allow this kind of customization, knowing
that the other things running on my server can do it?
--
Michael

On 12/14/2014 06:36 PM, Magnus Hagander wrote:
> A separate GUC seems kind of weird. Wouldn't it be better with something
> like %(format)t or such in the log_line_prefix itself in that case? That
> could also be expanded to other parameters, should we need them?

%t isn't the only thing that prints timestamps in the logs, e.g:

LOG: database system was shut down at 2014-12-15 15:30:15 EET

- Heikki