Tricky Time

I was looking at logs yesterday, and we noticed something odd in the syslog (I've edited this to make the problem more obvious):

Nov 18 12:03:16 portal-02 postfix/master[454]: 
Nov 18 12:03:20 portal-02 kernel: nfs: 
Nov 18 17:03:27 portal-02 apphbd[2763]: WARN: 
Nov 18 17:03:27 portal-02 apphbd[2763]: WARN: 
Nov 18 12:03:53 portal-02 kernel: nfs:
Nov 18 12:03:54 portal-02 kernel: nfs: 
Nov 18 12:04:17 portal-02 postfix/master[454]:
Nov 18 12:04:17 portal-02 postfix/master[454]:
Nov 18 17:04:26 portal-02 stunnel[24095]:
Nov 18 17:04:26 portal-02 stunnel[24122]:
Nov 18 17:04:26 portal-02 stunnel[24095]:
Nov 18 17:04:27 portal-02 stunnel[24122]:
Nov 18 17:04:27 portal-02 stunnel[24125]:
Nov 18 12:05:18 portal-02 postfix/cleanup[10163]:
Nov 18 12:05:18 portal-02 postfix/cleanup[10163]:

See it?

The time is "jumping around". It starts at noon-ish, and there are some entries at 5pm, and then some more at noon-ish. Very weird.

It took a good couple hours to track this down. And I should note that this is a Debian Linux syslog.... have you figured it out yet?

.

.

.

.

.

Hint time:

There are two things you need to know:

• That time stamp is the local time of the process that has the event.
• Processes set their time zone (their local time) when they start.

.

.

.

.

Got it yet?

The time zone (/etc/localtime) was changed after boot. Any processes that were restarted  - apphbd and stunnel, in our example - got the new time zone. Any processes that didn't restart stayed in the old time zone.

Seems simple once you know what's going on!