Red Hat Bugzilla – Bug 435472
some sshd log entries are in UTC rather than all in local time
Last modified: 2009-05-05 10:53:56 EDT
Description of problem:
The latest openssh-server package causes sshd log entries to appear in
inconsistent time zones. Some are logged in local time, and some in UTC.
Version-Release number of selected component (if applicable):
Steps to Reproduce:
1. Use ssh to connect to a rawhide system, login using valid username/password.
2. Look at sshd log entries in /var/log/secure, they're in local time
3. Use ssh to connect again, but Ctrl-C to abort without logging in
4. Look in /var/log/secure again, log entry is in UTC.
5. mkdir -p /var/empty/sshd/etc && cp -af /etc/localtime /var/empty/sshd/etc
6. Repeat steps 3&4, log entry is in local time.
Failed ssh logins cause sshd log entries in UTC rather than local time.
All syslog entries in local time.
Changelog in openssh-server package includes this entry...
* Tue Nov 20 2007 Tomas Mraz <firstname.lastname@example.org> - 4.7p1-4
- do not copy /etc/localtime into the chroot as it is not
necessary anymore (#193184)
I suspect this may have led to the problem. Commands in step 5 above restore
functionality from older /etc/rc.d/init.d/sshd script, which seems to correct
That's supposed to be fixed in rsyslog. It should always use local time in the
syslog entries and not the time sent from client.
See also bug 231326
according to RFC3339,
it seems that syslog should use timestamp specified in received message if
It's actually more rfc 3164 that matters. However, 3164 is an information
document, so it does not require anything. However (again), the spirit in syslog
rfc series (rfc 3195, upcoming RFCs, most importantly syslog-protocol) is that a
syslog receiver MUST use the time information provided in the message.
HOWEVER (next one) that doesn't imply it must write that time to the log file
(or whereever). So a device-received UTC timestamp may be converted to local
time by the syslogd. Unfortunately, timezone conversion is not yet supported by
rsyslog - this is a feature upcoming with function-calls inside the expression
engine (roughly a month away from now). Received time also is often not correct.
Rsyslog for this case supports two timestamps: the one from the device, and the
other one generated by itself, at time of reception.
The default template uses the device timestamp (if present). To change that, use
a different template, e.g.:
$template localtime,"%timegenerated% %HOSTNAME% %syslogtag%%msg:::drop-last-lf%\n"
The timestamp may be a bit delayed (depending on how long the message travelled
in the network), but this usually should pose no problem. At least it is consistent.
A word of warning, though: if the client rsyslog is using queues and restarts to
submit messages without loss when the receiver is down, there *is* is notable
difference between the two timestamps! (hours, days, depending on how long the
system was down).
Would it be possible to just modify the default template to use the generated
timestamp for messages received over unix sockets?
brief from the pda: is is tricky and opens up a can of worms. some use cases require parsing hostname and timestamp (e.g. if an external relay - think rfc3195d - is being used via that interface). Also templates have nothing to do with what the input source is. I can add some config directives to allow modifying these things, but there is no way this can happen by default - it breaks to much, including standards-compliance. My advise is to fix the root problem, though...
I have reviewed the linked bug entries - and I have to admit I am a bit confused
now. Is sshd actually logging a a) wrong timestamp or b) a correct timestamp,
but in a different timezone.
If it is b), then the actual problem is not parsing, but the fact that rsyslog,
in an effort to be compatible with sysklogd, drops the timezone information when
logging. What we could do is convert the timestamp to a consistent zone in that
case. I am still not sure if we can do this by default... More feedack is deeply
I don't understand the mechanics of the syslog protocol enough to give you a
definitive answer, Rainer, but based on my observations I'd say "b) a correct
timestamp, but in a different timezone". My local time zone is CST (UTC -0600),
and when sshd logs failed logins the time offset is exactly 6 hours from when it
logs successful ones. When I copy /etc/localtime to /var/empty/sshd/etc, all
log entries are consistently logged in localtime, so this suggests pretty
strongly that when the localtime file isn't in that directory, failed logins are
logged with the correct time, but in UTC rather than local time (CST).
All this discussion about which time should go into the logs is interesting, but
in terms of finding an expedient solution to the problem, I think the answer is
pretty apparent: sshd should at least try to give its timestamp to syslog in a
consistent manner, whether or not the attempted login is successful or not, and
whether or not syslog chooses to use sshd's timestamp or its own. Restoring
the localtime file to /var/empty/sshd/etc seems to fix that problem and restore
the correct functioning we had in older versions, so why not do that, regardless
of what other changes eventually get made to syslog and/or its configuration?
It is b) but note that the message from glibc syslog(3) doesn't contain the
timezone information at all so I don't know how would you detect this and convert.
Gilles: of course I can and will do that but I think the rsyslog problem is
just a quick note: you can verify the complete timestamp by simply including it.
This is done as follows:
$template rfc3339,"%TIMESTAMP:::date-rfc3339% %HOSTNAME%
Be careful: each of them is exactly on one line and the properties in the
template are case-sensitive (I was foolish when I did this and it will soon
More comments follow.
Rainer, btw the rfc3195d messages will be sent to socket marked with the ':' on
command line so this kind of socket could be excluded from the special timestamp
But I understand that it is a little bit hackish.
I am looking at a clean way to do it. rfc3195d was quite a hack and will go away
soon. The problem still remains.
HOWEVER, I see we are digging *much* deeper than sshd (following the other bug
reports made this clear to me). The actual question is "can we trust the
timestamp?". The general answer is: no (that's why we provide the receive
timestamp too). For local sockets, the time difference between the message
generation stamp and its reception at the syslogd should be very minimal. So it
can be a good idea to ignore the timestamp provided and always (consistently)
use time of reception.
So, yes, a way to go is to instruct the input module (that reads to local
socket) to ignore the timestamp (should it simply discard it or leave it inside
the message...?) and use the reception time instead. Of course, there are valid
cases where this is not desired, so it must be an option.
The big question is what the default should be. What makes it especially hard
here is that sysklogd, in different versions and in different distros, seems to
have different ways to handle it. So maybe this means its not important at all
and we can default to ignore the timestamp? Not an easy question. I've also
begun to ask around at other places. If different distros have different needs,
we may add a configure option to set the default -- but I really don't like that
/sysklogd/syslogd.c version 1.44
* Sun Nov 7 12:28:47 CET 2004: Martin Schulze <email@example.com>
* Discard any timestamp information found in received syslog
* messages. This will affect local messages sent from a
* different timezone.
It's almost 4 years, since sysklogd upstream starts to ignore timestamps. I
think we can take this into account. Rainer, make up your mind about the
default behavior. On the other side, beta freeze is coming next week, so if
you need some more time I suggest to fix this problem on openssh-server side.
I think it would be nice to solve this issue before beta freeze :)
OK, that's convincing ;) Let me now look what it actually takes to code...
Question: how about the kernel log (imklog)? Should it also be possible to
ignore the timestamp there?
I don't see any problems with that.
OK, I also have good news. The change is quite trivial. I'll add config
directives and they default to ignoring the timestamp received on unix sockets.
I am sure I can complete that today and release it is part of 3.12.1, either
today or tomorrow.
change is committed and now in CVS head.
rsyslog-3.12.1-1.fc9 was built in rawhide, it will be available in repo soon.
I'm closing this issue. If the problem persist feel free to reopen. thnx.
The rsyslog-3.12.1-1.fc9 update seems to have fixed the problem for me. After
updating, I removed the /var/empty/sshd/etc/localtime file, restarted the sshd
service, and redid my tests, and all log entries are in local time. Thanks!