Bug 435472 - some sshd log entries are in UTC rather than all in local time
some sshd log entries are in UTC rather than all in local time
Status: CLOSED RAWHIDE
Product: Fedora
Classification: Fedora
Component: rsyslog (Show other bugs)
rawhide
All Linux
low Severity medium
: ---
: ---
Assigned To: Peter Vrabec
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2008-02-29 10:56 EST by Gilles Detillieux
Modified: 2009-05-05 10:53 EDT (History)
4 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2008-03-07 06:34:52 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Gilles Detillieux 2008-02-29 10:56:39 EST
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@redhat.com> - 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.
Comment 1 Tomas Mraz 2008-02-29 11:14:55 EST
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?
Comment 2 Tomas Mraz 2008-02-29 11:18:07 EST
See also bug 231326
Comment 3 Peter Vrabec 2008-03-05 12:22:58 EST
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.
Comment 4 Rainer Gerhards 2008-03-05 12:55:42 EST
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
Comment 5 Tomas Mraz 2008-03-05 13:08:01 EST
Would it be possible to just modify the default template to use the generated
timestamp for messages received over unix sockets?
Comment 6 Rainer Gerhards 2008-03-05 14:16:26 EST
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
Comment 7 Rainer Gerhards 2008-03-05 15:12:08 EST
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
Comment 8 Gilles Detillieux 2008-03-05 15:33:17 EST
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?
Comment 9 Tomas Mraz 2008-03-05 15:38:31 EST
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.
Comment 10 Rainer Gerhards 2008-03-05 15:44:16 EST
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
Comment 11 Tomas Mraz 2008-03-05 15:49:59 EST
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.
Comment 12 Rainer Gerhards 2008-03-05 16:07:00 EST
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
Comment 13 Peter Vrabec 2008-03-06 05:55:10 EST
/sysklogd/syslogd.c version 1.44
* Sun Nov  7 12:28:47 CET 2004: Martin Schulze <joey@infodrom.org>
*      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 :)
Comment 14 Rainer Gerhards 2008-03-06 07:50:18 EST
OK, that's convincing ;) Let me now look what it actually takes to code...

Rainer
Comment 15 Rainer Gerhards 2008-03-06 08:11:22 EST
Question: how about the kernel log (imklog)? Should it also be possible to
ignore the timestamp there?
Comment 16 Tomas Mraz 2008-03-06 08:18:02 EST
I don't see any problems with that.
Comment 17 Rainer Gerhards 2008-03-06 08:21:44 EST
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
Comment 18 Rainer Gerhards 2008-03-06 08:55:18 EST
change is committed and now in CVS head.
Comment 19 Peter Vrabec 2008-03-07 06:34:52 EST
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.
Comment 20 Gilles Detillieux 2008-03-12 12:01:41 EDT
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!

Note You need to log in before you can comment on or make changes to this bug.