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): 4.7p1-8.fc9 How reproducible: Always 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. Actual results: Failed ssh logins cause sshd log entries in UTC rather than local time. Expected results: All syslog entries in local time. Additional info: Changelog in openssh-server package includes this entry... * Tue Nov 20 2007 Tomas Mraz <tmraz> - 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 syslog entries.
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. Peter?
See also bug 231326
according to RFC3339, http://www.faqs.org/rfcs/rfc3339.html it seems that syslog should use timestamp specified in received message if it's valid.
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). Rainer
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... rainer
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 appreciated. Rainer
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 still valid.
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% %syslogtag%%msg:::drop-last-lf%\n" *.* -/var/log/whaterver;rfc3339time 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 change...). More comments follow. Rainer
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 handling too. 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 idea... Rainer
/sysklogd/syslogd.c version 1.44 * Sun Nov 7 12:28:47 CET 2004: Martin Schulze <joey> * 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... Rainer
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. Rainer
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!