Future timestamps in /var/log/secure

I found a while ago in /var/log/secure that for an invalid ssh login attempt the ssh Bye Bye line is in the future. I have searched the web and can not find a reason for the future time in the log.

Here is a sample. Repeated lines are shown once in first part

grep "210.212.145.152" /var/log/secure

Feb 26 09:43:13 mx sshd[18117]: Did not receive identification string from 210.212.145.152
Feb 26 09:50:33 mx sshd[19100]: Invalid user 0admin from 210.212.145.152
Feb 26 09:50:36 mx sshd[19106]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=210.212.145.152
Feb 26 09:50:38 mx sshd[19102]: Failed password for invalid user 0admin from 210.212.145.152 port 39902 ssh2
Feb 26 17:50:38 mx sshd[19113]: Received disconnect from 210.212.145.152: 11: Bye Bye

grep -A1 -B1 "sshd\[19118\]: Received disconnect from 210.212.145.152: 11: Bye Bye" /var/log/secure

Feb 26 17:50:38 mx sshd[19115]: Received disconnect from 210.212.145.152: 11: Bye Bye
Feb 26 17:50:38 mx sshd[19118]: Received disconnect from 210.212.145.152: 11: Bye Bye
Feb 26 09:52:39 mx proftpd[17297]: mx.example.com (208.xxx.xxx.xxx[208.xxx.xxx.xxx]) - FTP no transfer timeout, disconnected

Can anyone explain the future time stamp on the Bye Bye lines?

OS is Centos 5.4, FYI

Isn't the timestamps inserted by syslog rather then the reporting program itself?

What syslog do you use - classic (ie: sysklogd) or a modern one like rsyslog? It almost looks like the timezone got changed from local to GMT or similar, then swapped back (as odd as it may sound).

Perhaps time to file a bug report with the author of the syslog daemon you use?

Been a long time since I've dealt with this stuff, but it looks like the
shell for proftpd has a different TZ from the one running the other
stuff. (syslogd runs in the shell of the caller, right?)

I happend upon this ( https://bugzilla.redhat.com/show_bug.cgi?id=193184 )
which seems to suggest/explain the occurrence. I know it was mentioned to be
in the CentOS distro, but I think this might have been adopted into that
distro as well since I see the same issues on a RedHat Distro. Not sure if
the article helps or hinders but good food for thought.

-Joe Blanchard

Isn't the timestamps inserted by syslog rather then the reporting
program itself?

that's my understanding also (clarification: syslogs of your server have
timestamps of your syslegsserver's time, IMHO)
eg: on my Debain systems I don't split the logging to /var/log/secure, I
can usually handle a large log OK, but it's easy enough to get the
authpriv* stuff to log to /v/l/secure if needed. So, my point is,
syslogd.conf tells syslogd where to put them, and it stamps the time for
each entry.

What syslog do you use - classic (ie: sysklogd) or a modern one like
rsyslog? It almost looks like the timezone got changed from local to
GMT or similar, then swapped back (as odd as it may sound).

On a cautionary note, I've seen tz-change shenanigans to mask
unauthorised access before, so might be a good time to have quick poke
around with a tinfoil hat on, just in case. Don't have a heart attack
tough, not yet :slight_smile:

Gord

It is classic syslogd
syslogd -v

syslogd 1.4.1

I was thinking timezone but we are PST (-8:00) so I can not explain the
+12:00 difference.

the proftpd line happened to be the next line in the log. the
next simular ssh lines looks like (duplicate removed)

Feb 26 10:08:48 mx sshd[22165]: Did not receive identification string from UNKNOWN
Feb 26 10:09:27 mx sshd[22261]: Failed password for root from 219.137.192.231 port 54111 ssh2

The syslog message sent to the local unix socket (/dev/log
or /dev/syslog) may contain a timestamp, in which case, that timestamp
may be used instead of the local time. As the syslog protocol defines
that timestamps are localtime, without any specification of what
timezone localtime actually is, the TZ environment variable of the
application calling syslog() will affect the timestamp placed in the
log.

William

whois gives India? 12 hrs maybe? From a brief recon of it looks a bit,
shall we say, "soft" - get your hat on just in case.

I can confirm that changing my time on the ssh client machine end does
not reproduce this on my Debain machines, no matter where the entries
are logged to.

Sorry I don't have any RH/Centos I can test with at this time of day,
even virtualised - anyone ?

Gord

is it possible that a local user changed the time (maybe with a GUI app)
around the time of these attempts?

(failed attempts like this are normal for a machine hooked to the
internet without ACLs BTW, the problem is the strange timestamp <<for
the benefit of casual onlookers in the thread)

Gord

aha! there you go, mine doesn't but maybe yours does?

Gord

Feb 26 09:50:38 mx sshd[19102]:
Feb 26 17:50:38 mx sshd[19113]:

That's 8 hours difference, one logged in UTC, one in local. Where do you
see +12?

The specification for the syslog protocol is that timestamps embedded in
the message should be used instead of syslogd's time. Most syslog
daemons as a result apply this concept to both local and remote
messages.

You have to keep in mind that syslogd can also send/receive messages
to/from remote destinations.

William

It's easier to see these timezone issues when using an ISO timestamp
like "2010-02-26T06:26:17-08:00" instead of the old style that omits the
timezone.

~Seth

It might be prudent to mention that all of the connections of this type are
null routed via an iptables drop rule after three failed attempts via a "home
grown" daemon similar to DENYHOSTS. All traffic from host is DENIED for 120 days
unless we manually over ride it.

I do appreciate the cautionary, "better have a look around just to be sure" comments

Wade

That does make sense. I will try to simulate that with a temporary
virtual machine as a different timezone.

Wade