[syslog-ng] Timestamp inconsistency

[Balazs Scheidler]

On Sun, 2007-06-24 at 18:13 -0400, Tim Boyer wrote:
> I'm running 2.0.0, and the docs say that
> 
>    The sender can specify the timezone of the messages. If the incoming
>    message includes a timezone it is associated with the message. Otherwise,
>    the local timezone is assumed.
> 
> I'm not specifying any timezone, but I'm seeing a bunch of messages stamped
> UTC mixed in with EDT, which makes the log a bit... weird:
> 
> Jun 24 21:38:01 tolstoy.denmantire.com sshd[7949]: Connection closed by
> 192.168
> Jun 24 17:40:01 tolstoy.denmantire.com crond[7987]: (root) CMD
> (/usr/lib/sa/sa1
> Jun 24 21:43:01 tolstoy.denmantire.com sshd[7994]: Connection closed by
> 192.168
> Jun 24 17:44:34 tolstoy.denmantire.com syslog-ng[11618]: Log statistics;
> droppe
> Jun 24 21:48:02 tolstoy.denmantire.com sshd[8036]: Connection closed by
> 192.168
> Jun 24 17:50:01 tolstoy.denmantire.com crond[8082]: (root) CMD
> (/usr/lib/sa/sa1
> Jun 24 21:53:03 tolstoy.denmantire.com sshd[8107]: Connection closed by
> 192.168

This is probably an SSHD bug as someone else already pointed out.

> 
> So just to test, I did this:
> 
> TZ="UTC+23:56" logger "Look I'm logging from yesterday"
> 
> and sure enough, it logged it as yesterday.

Yes, that message still did not contain a timezone, as logger does not
send it. Specifying the local timezone for logger only changed it the
timestamp as it was sent to syslog-ng.

> 
> So I tried to explicitly set the time zones:
> 
> options {
>   send_time_zone(-04:00);
>   recv_time_zone(-04:00);
> 
> destination dtolstoy_all {
>   file("/var/log/tolstoy.log" owner(root) group(hobbit) perm(0640)
> time_zone(-04:00));
> 
> Restarted syslog-ng, and:
> 
> Jun 24 17:09:00 tolstoy.denmantire.com syslog-ng: syslog-ng startup
> succeeded
> Jun 23 21:13:09 tolstoy.denmantire.com tim: Look I'm logging from yesterday

The timezone conversions that you specified (all incoming messages
treated as -04:00 and then converted to -04:00 as written out), is a
noop. 

> 
> I don't understand why it's not logging as local time without me having to
> do anything.  And I _really_ don't understand why the explicit instructions
> don't work.
> 
> Pounters in the the right direction appreciated...

When an incoming message specifies a timezone (which logger will not do
by itself), syslog-ng uses that information to convert the time to UTC
(e.g. GMT+0). If the message does not contain such information in the
first place, it will _assume_ that it comes from the local timezone. The
explicit timezone instructions only change this assumption.

If a program generates messages using an incorrect timezone (e.g. ssh,
or in the case above logger), and it does _NOT_ include this timezone
information in the message (which the legacy syslog protocol cannot do),
then syslog-ng has no means to do anything without further information.
What you can do however, is to force sshd to log to a different socket
instead of /dev/log and associate a different recv_time_zone() to the
source handling this different socket. This is not easy, as there's no
means to override the /dev/log socket when using the syslog functions
from libc (which sshd does).

So the easiest fix is to fix sshd.

-- 
Bazsi