1

I have noticed that my syslog reports incorrect time for some authentication entries. The typical behaviour looks like this: 

Feb 16 13:32:20 dev sshd[29537]: Invalid user oracle from 110.188.0.123
Feb 16 12:32:20 dev sshd[29538]: input_userauth_request: invalid user oracle
Feb 16 13:32:20 dev sshd[29537]: pam_unix(sshd:auth): check pass; user unknown
Feb 16 13:32:20 dev sshd[29537]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=110.188.0.123
Feb 16 13:32:20 dev sshd[29537]: pam_succeed_if(sshd:auth): error retrieving information about user oracle
Feb 16 13:32:22 dev sshd[29537]: Failed password for invalid user oracle from 110.188.0.123 port 64368 ssh2
Feb 16 12:32:23 dev sshd[29538]: Received disconnect from 110.188.0.123: 11: Bye Bye

Notice how the hour swaps back and forth. Has anybody seen a similar behaviour? What might cause this? It seems systematic and it's the same entries for each connection attempt that are reported an hour earlier than they should be. System clock is GMT. Timezone GMT+1.

pehrs
  • 8,749
  • 29
  • 46

2 Answers2

1

Note that one process 29537 always sends messages marked one hour later than process 29538. Syslog protocol specifies that clients send messages timestamped in a textual MMM DD HH:MM:SS format, not a wise thing at all.

On UNIX/Linux there is one system time (number of seconds since 1970), but each process on a system can interpret it as if it was placed in a different timezone. How this is handled, each process that wants to convert number-of-seconds to the actual HH:MM:SS text, first reads $TZ environment variable. Because each process has its very own separate environment, each process can have a different value of $TZ and display dates from a different time zone.

On your system, if $TZ has been changed in /etc/environment, but sshd process has not been restarted since that time, it will use the original $TZ. So please restart all sshd processes and repeat your test.

kubanczyk
  • 13,502
  • 5
  • 40
  • 55
  • Restarting sshd did not change the behaviour. Nor did restarting the whole server. Interestingly enough I see "sshd[2465]: error: Bind to port 22 on 0.0.0.0 failed: Address already in use." during the startup. IPv6 binds without problem. Netstat -ap gives me the line "tcp *:ssh *:* LISTEN 2465/sshd" – pehrs Feb 17 '10 at 20:56
  • No, that's normal. Which sshd is reporting "wrong" time. The father (long-running process) or child? This repeats on every connection attempt, even for a different user and different client machine?? – kubanczyk Feb 17 '10 at 22:33
  • None of the two processes listed in the secure log matches the pid of the long running service. I can see the same behaviour for all failed authentication attempts, regardless of account, authentication method and source. On successful attempts only one process reports in the log, and it has the correct time. – pehrs Feb 17 '10 at 23:04
  • Reinstalling the server finally removed the problem. Still no idea what caused it. – pehrs Mar 07 '10 at 10:33
0

You don't happen to have two syslog daemon running at the same time, one of which has not been configured properly (i.e. you changed the time when the daylight saving came into effect and did not restart it)? Then a race condition affects which daemon intercepts the syscall and writes to disk.

lorenzog
  • 2,719
  • 1
  • 18
  • 24
  • Only one syslog daemon is running on the system, otherwise that would explain it. Restarting the syslog daemon did not change the behaviour. – pehrs Feb 17 '10 at 14:02