syslog() always sends GMT timestamps

syslog() always sends GMT timestamps

[orc]

In syslog() there is a call to gmtime_r() instead of localtime_r() which applies timezone offset. Logs are being collected with GMT timestamps which is a bit misleading.

Re: syslog() always sends GMT timestamps

[Rich Felker]

On Tue, Jan 28, 2014 at 07:39:38PM +0800, orc wrote:
> In syslog() there is a call to gmtime_r() instead of localtime_r()
> which applies timezone offset. Logs are being collected with GMT
> timestamps which is a bit misleading.

The standard doesn't specify whether these timestamps are local or
gmt, and does not allow modifying the global state that localtime
modifies and which localtime_r is also allowed to modify. POSIX allows
localtime_r not to modify this global state, but making such an
implementation is non-trivial. And moreover, since POSIX does not
specify syslog to access the TZ variable, accessing it would make
syslog non-safe with respect to modifying TZ from other threads, which
is probably non-conforming. These are the technical reasons I made
musl's syslog use gmt.

Aside from that, I just think it's a bad idea to put local time in the
syslog, since different processes writing to syslog might have
different timezones set, leading to confusingly interleaved timestamps
that are hard to make sense of. Others may disagree on this (it's a
policy matter rather than a technical one) but it was probably part of
my motivation too.

Rich

Re: syslog() always sends GMT timestamps

[orc]

Rich Felker <dalias@aerifal.cx> пишет:
>On Tue, Jan 28, 2014 at 07:39:38PM +0800, orc wrote:
>> In syslog() there is a call to gmtime_r() instead of localtime_r()
>> which applies timezone offset. Logs are being collected with GMT
>> timestamps which is a bit misleading.
>
>The standard doesn't specify whether these timestamps are local or
>gmt, and does not allow modifying the global state that localtime
>modifies and which localtime_r is also allowed to modify. POSIX allows
>localtime_r not to modify this global state, but making such an
>implementation is non-trivial. And moreover, since POSIX does not
>specify syslog to access the TZ variable, accessing it would make
>syslog non-safe with respect to modifying TZ from other threads, which
>is probably non-conforming. These are the technical reasons I made
>musl's syslog use gmt.
>
>Aside from that, I just think it's a bad idea to put local time in the
>syslog, since different processes writing to syslog might have
>different timezones set, leading to confusingly interleaved timestamps
>that are hard to make sense of. Others may disagree on this (it's a
>policy matter rather than a technical one) but it was probably part of
>my motivation too.

Thank you for your detailed explanation about cross-process and cross-user issues. Since my systems are probably not going to be true multi-user interconnected and sharing resources (say, for example, sending logs to central syslog server), I want to keep "old" behavior of syslog(). Can you give advices how I can do that in more safe way? If it is not possible, what breakage can occur if I will go with localtime_r()?
Thanks!

>
>Rich

Re: syslog() always sends GMT timestamps

[Rich Felker]

On Wed, Jan 29, 2014 at 07:45:25PM +0800, orc wrote:
> Thank you for your detailed explanation about cross-process and
> cross-user issues. Since my systems are probably not going to be
> true multi-user interconnected and sharing resources (say, for
> example, sending logs to central syslog server), I want to keep
> "old" behavior of syslog(). Can you give advices how I can do that
> in more safe way? If it is not possible, what breakage can occur if
> I will go with localtime_r()?
> Thanks!

Really it's unlikely to break anything if you just use localtime_r,
but the behavior is testably/observably incorrect per the standard and
could interact badly with multithreaded programs which change their
own environments at runtime (note that the same breakage probably
occurs on glibc and elsewhere though; musl just tries to be better
than that).

So really this is a matter you could pretty easily change locally, but
where for correctness and robustness the change isn't acceptable
upstream. If you (or others) still have interest in trying to get
syslog with local time upstream, we'll need to have a discussion on
how it could be done safely.

Rich

Re: syslog() always sends GMT timestamps

[Szabolcs Nagy]

* Rich Felker <dalias@aerifal.cx> [2014-01-29 23:33:44 -0500]:
> So really this is a matter you could pretty easily change locally, but
> where for correctness and robustness the change isn't acceptable
> upstream. If you (or others) still have interest in trying to get
> syslog with local time upstream, we'll need to have a discussion on
> how it could be done safely.

btw currently syslog does not print year so even if
at a later point one tries to parse the date and
display it in local time it will be hard to do so

imo the standard timestamp format is '%Y-%m-%d %H:%M:%S'
(maybe with T instead of space, but that's less readable)
it is a bit longer than the current one, but at least
clear, not nl_langinfo dependent (in case someone adds
LC_TIME support for other languages) and reversible

(the real iso8601/rfc3339 standard is '%Y-%m-%dT%H:%M:%SZ')

Re: syslog() always sends GMT timestamps

[Rich Felker]

On Thu, Jan 30, 2014 at 01:04:13PM +0100, Szabolcs Nagy wrote:
> * Rich Felker <dalias@aerifal.cx> [2014-01-29 23:33:44 -0500]:
> > So really this is a matter you could pretty easily change locally, but
> > where for correctness and robustness the change isn't acceptable
> > upstream. If you (or others) still have interest in trying to get
> > syslog with local time upstream, we'll need to have a discussion on
> > how it could be done safely.
> 
> btw currently syslog does not print year so even if
> at a later point one tries to parse the date and
> display it in local time it will be hard to do so
> 
> imo the standard timestamp format is '%Y-%m-%d %H:%M:%S'
> (maybe with T instead of space, but that's less readable)
> it is a bit longer than the current one, but at least
> clear, not nl_langinfo dependent (in case someone adds
> LC_TIME support for other languages) and reversible
> 
> (the real iso8601/rfc3339 standard is '%Y-%m-%dT%H:%M:%SZ')

I'd like more input from users. I don't think this is something we
should change immediately before 1.0 or in the 1.0.x stable series,
but you've raised very good points that should be addressed at some
point. If we add build customization at some point in the future, this
may be an area we should consider allowing some degree of
customization. But of course I'm a bit hesitant to start doing that.

Rich

Re: syslog() always sends GMT timestamps

[Laurent Bercot]

On 2014-01-31 16:54, Rich Felker wrote:
[about syslog]
> I'd like more input from users.

  My input is that you shouldn't devote any more brain power to syslog
than is absolutely necessary to be barely standards-conformant.

  Software authors should not be encouraged to use syslog; instead,
they should be educated not to.
  http://skarnet.org/software/s6/s6-log.html#diesyslogdiedie

  As for timestamps, well, the right format to write them in is
obviously neither UTC nor local time, but TAI64N. :)

-- 
  Laurent

Re: syslog() always sends GMT timestamps

[Szabolcs Nagy]

* Laurent Bercot <ska-dietlibc@skarnet.org> [2014-01-31 17:26:23 -0800]:
>  As for timestamps, well, the right format to write them in is
> obviously neither UTC nor local time, but TAI64N. :)

yes there is nothing clearer than a 24 digit hexadecimal number
representing time to the nanosecond

at least the last 3-4 digits in the log can be used as a random
sequence

(i've seen this in practice and have no idea how anybody could
ever think that it's a good idea.. must be some sysadmin logic
that is beyond the reach of average mortals)

Re: syslog() always sends GMT timestamps

[Christian Wiese]

On Sat, 1 Feb 2014 10:09:14 +0100
Szabolcs Nagy <nsz@port70.net> wrote:

> * Laurent Bercot <ska-dietlibc@skarnet.org> [2014-01-31 17:26:23
> -0800]:
> >  As for timestamps, well, the right format to write them in is
> > obviously neither UTC nor local time, but TAI64N. :)
> 
> yes there is nothing clearer than a 24 digit hexadecimal number
> representing time to the nanosecond
>
> at least the last 3-4 digits in the log can be used as a random
> sequence
> 
> (i've seen this in practice and have no idea how anybody could
> ever think that it's a good idea.. must be some sysadmin logic
> that is beyond the reach of average mortals)

Of course the format is not very easy to read for humans but quite
useful for machine processing, which is much more important imo because
you will barely have an humanoid sitting there in front of the screen
and looking for suspicious log entries.
If a human needs to look at logs with TAI64N time stamps he/she is
supposed to pipe the the log through a filter like 'tai64nlocal' which
simply transforms the time stamp into a human friendly format.

Besides that I think TAI64N time stamps can be quite useful in the case
you need to correlate logs from a lots of hosts that have different
local time settings. Doing this with logs that use local time stamps
will be a task that is nearly impossible imo or at least needs quite
some effort.

Cheers,
Chris

Re: syslog() always sends GMT timestamps

[Laurent Bercot]

On 2014-02-01 01:09, Szabolcs Nagy wrote:

> yes there is nothing clearer than a 24 digit hexadecimal number
> representing time to the nanosecond
>
> at least the last 3-4 digits in the log can be used as a random
> sequence
>
> (i've seen this in practice and have no idea how anybody could
> ever think that it's a good idea.. must be some sysadmin logic
> that is beyond the reach of average mortals)

  I was half-trolling, but since you bit the hook:

  Historically, logs were made to be read by human beings, so it
made sense to print timestamps in a human-readable format. But it
is less and less the case. Logs are getting more and more
automatically processed, filtered, aggregated, analyzed, which is
a good thing. Humans nowadays only look at raw textual log data once
everything else has failed, including visualizing them in some web
interface that also processes them for display.

  So it actually makes more sense to write logs in a format that is
easily parsable and usable by *computers*, and timestamps are a big
part of it. Human time is complex to understand for computers (and
even for humans not living in the same time zone). TAI64N is simple,
and makes processing easy as pie. (Mmmm... pie.) Merging log files
chronologically ? Just cat all your log files together, pipe them
through sort, done. Oh, and it works with log files from other
machines all around the world, without a concern for timezones or
human time quirks such as DST, too. Want to strip the timestamps
for some reason ? Pipe your logs through "cut -c27-", done.

  And people can even read the raw files too, they just have to
run "s6-tai64nlocal < logfile | less" instead of "less logfile",
which is the simplest processing you could think of - a UNIX filter.
(I've heard that Great Sysadmins can understand TAI64N directly in
the text, but I couldn't tell, I'm not yet part of the Circle.)

  So, dear initiate, now that you know the greatness of automated
processing and of Unix filters, and have shaken off the myth that
logs have to be read exactly as they were written, you have risen
above average mortals, and are now a Sysadmin. Congratulations and
welcome !

-- 
  Laurent

Re: syslog() always sends GMT timestamps

[Paul Schutte]

[-- Attachment #1: Type: text/plain, Size: 2909 bytes --]

I have to chime in here.

The venerable squid proxy has generated logs with unix epoc timestamps for
ages and it never has stopped anyone from reading those.
I am all for the ISO date format, but it makes a lot of sense to have it in
either TAI64N or epoch time.
It is trivial to filter those for human consumption as mentioned. On the
other hand if the log was in some human readable form one has to start to
dabble with inefficient things like Time::ParseDate in perl to make
computers understand it. Not to mention the time zone mess.

Just my 2 cents.

Regards
Paul


On Sat, Feb 1, 2014 at 5:48 PM, Laurent Bercot <ska-dietlibc@skarnet.org>wrote:

> On 2014-02-01 01:09, Szabolcs Nagy wrote:
>
>  yes there is nothing clearer than a 24 digit hexadecimal number
>> representing time to the nanosecond
>>
>> at least the last 3-4 digits in the log can be used as a random
>> sequence
>>
>> (i've seen this in practice and have no idea how anybody could
>> ever think that it's a good idea.. must be some sysadmin logic
>> that is beyond the reach of average mortals)
>>
>
>  I was half-trolling, but since you bit the hook:
>
>  Historically, logs were made to be read by human beings, so it
> made sense to print timestamps in a human-readable format. But it
> is less and less the case. Logs are getting more and more
> automatically processed, filtered, aggregated, analyzed, which is
> a good thing. Humans nowadays only look at raw textual log data once
> everything else has failed, including visualizing them in some web
> interface that also processes them for display.
>
>  So it actually makes more sense to write logs in a format that is
> easily parsable and usable by *computers*, and timestamps are a big
> part of it. Human time is complex to understand for computers (and
> even for humans not living in the same time zone). TAI64N is simple,
> and makes processing easy as pie. (Mmmm... pie.) Merging log files
> chronologically ? Just cat all your log files together, pipe them
> through sort, done. Oh, and it works with log files from other
> machines all around the world, without a concern for timezones or
> human time quirks such as DST, too. Want to strip the timestamps
> for some reason ? Pipe your logs through "cut -c27-", done.
>
>  And people can even read the raw files too, they just have to
> run "s6-tai64nlocal < logfile | less" instead of "less logfile",
> which is the simplest processing you could think of - a UNIX filter.
> (I've heard that Great Sysadmins can understand TAI64N directly in
> the text, but I couldn't tell, I'm not yet part of the Circle.)
>
>  So, dear initiate, now that you know the greatness of automated
> processing and of Unix filters, and have shaken off the myth that
> logs have to be read exactly as they were written, you have risen
> above average mortals, and are now a Sysadmin. Congratulations and
> welcome !
>
> --
>  Laurent
>
>

[-- Attachment #2: Type: text/html, Size: 3685 bytes --]

Re: syslog() always sends GMT timestamps

[orc]

1 февраля 2014 г. 8:54:19 KRAT, Rich Felker <dalias@aerifal.cx> пишет:
>On Thu, Jan 30, 2014 at 01:04:13PM +0100, Szabolcs Nagy wrote:
>> * Rich Felker <dalias@aerifal.cx> [2014-01-29 23:33:44 -0500]:
>> > So really this is a matter you could pretty easily change locally,
>but
>> > where for correctness and robustness the change isn't acceptable
>> > upstream. If you (or others) still have interest in trying to get
>> > syslog with local time upstream, we'll need to have a discussion on
>> > how it could be done safely.
>> 
>> btw currently syslog does not print year so even if
>> at a later point one tries to parse the date and
>> display it in local time it will be hard to do so
>> 
>> imo the standard timestamp format is '%Y-%m-%d %H:%M:%S'
>> (maybe with T instead of space, but that's less readable)
>> it is a bit longer than the current one, but at least
>> clear, not nl_langinfo dependent (in case someone adds
>> LC_TIME support for other languages) and reversible
>> 
>> (the real iso8601/rfc3339 standard is '%Y-%m-%dT%H:%M:%SZ')
>
>I'd like more input from users. I don't think this is something we
>should change immediately before 1.0 or in the 1.0.x stable series,
>but you've raised very good points that should be addressed at some
>point. If we add build customization at some point in the future, this
>may be an area we should consider allowing some degree of
>customization. But of course I'm a bit hesitant to start doing that.
>

I already patched my musl tree to run with localtime since it does not affect much of internal state as you noted.
IMHO I think musl wiki should have article about customization patches like this rather than configure options.
The libc itself is strict and sane.

>Rich