Summary: | app-admin/syslog-ng-3.6.2: scary time stamp jumps | ||
---|---|---|---|
Product: | Gentoo Linux | Reporter: | Toralf Förster <toralf> |
Component: | [OLD] Server | Assignee: | Mr. Bones. (RETIRED) <mr_bones_> |
Status: | RESOLVED UPSTREAM | ||
Severity: | normal | CC: | gentoo, gentoo, main.haarp, wols |
Priority: | Normal | ||
Version: | unspecified | ||
Hardware: | All | ||
OS: | Linux | ||
Whiteboard: | |||
Package list: | Runtime testing required: | --- |
Description
Toralf Förster
2014-12-22 19:41:34 UTC
How would this be caused by app-admin/syslog-ng? Wouldn't it be more plausible that it's the KVM that is messing with system time? syslog-ng3.6.1 has some obscure time jumps too (w/o any KVM) - so I expect syslog to be blamed. Maybe you're synching time in a scary way? Well, I'm prettu sure(In reply to Jeroen Roovers from comment #3) > Maybe you're synching time in a scary way? No, I fear, syslog-ng has to be blamed. Look at this messages : Dec 28 13:54:08 t44 tfoerste[17050]: huhu Dec 28 13:54:25 t44 polkitd[1699]: Operator of unix-session:/org/freedesktop/ConsoleKit/Session1 successfully authenticated as unix-user:root to gain TEMPORARY authorization for action org.libvirt.unix.manage for unix-process:17058:7696512 [<unknown>] (owned by unix-user:tfoerste) Dec 27 20:30:10 t44 kernel: tun: Universal TUN/TAP device driver, 1.6 Dec 27 20:30:10 t44 kernel: tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com> Dec 28 13:54:48 t44 tfoerste[17093]: haha This happended when I used virt-manager to start a KVM machine (the start of the guest fails due to not loaded net.br0 first) and urn the lgoger dcommand in another terminal before and after The timestamps shows that there's no bad time sycing. Instead syslog-ng is terrible wrong here, or ? and this is the outpout of : $> logger haha;sudo /etc/init.d/net.br0 start; logger hoho Dec 28 13:59:06 t44 tfoerste[17223]: haha Dec 27 20:35:35 t44 kernel: Bridge firewalling registered Dec 27 20:35:35 t44 kernel: device tap0 entered promiscuous mode Dec 27 20:35:35 t44 kernel: device br0 entered promiscuous mode Dec 28 13:59:56 t44 ntpd[3079]: Listen normally on 6 br0 192.168.1.254:123 Dec 28 14:00:01 t44 crond[17902]: pam_unix(crond:session): session opened for user root by (uid=0) Dec 28 14:00:01 t44 CROND[17904]: (root) CMD ([ ! -x /etc/cron.hourly/0anacron ] && { test -x /usr/sbin/run-crons && /usr/sbin/run-crons ; }) Dec 28 14:00:01 t44 crond[17903]: pam_unix(crond:session): session opened for user root by (uid=0) Dec 28 14:00:01 t44 CROND[17905]: (root) CMD (/usr/lib/sa/sa1 60 60) Dec 28 14:00:01 t44 CROND[17902]: pam_unix(crond:session): session closed for user root Dec 28 14:00:17 t44 tfoerste[17986]: hoho I had such scary issues, and likely even some corruption of data, with syslog-ng-3.6.1 two weeks ago and previously with syslog-ng-3.5.6 two months ago. Reverting to syslog-ng-3.4.6 in both cases resolved the issues. Pls. see: Syslog-ng from Delay Logging to BrokenPipe/no Logging http://forums.gentoo.org/viewtopic-t-1001994.html Cheers! > > Reverting to syslog-ng-3.4.6 in both cases resolved the issues. Reverting to syslog-ng-3.4.8 (8, not 6), sorry for the typo. And I wrote more on the forums: > Syslog-ng from Delay Logging to BrokenPipe/no Logging > http://forums.gentoo.org/viewtopic-t-1001994.html Cheers! > And I wrote more on the forums: > > Syslog-ng from Delay Logging to BrokenPipe/no Logging And I revisited the topic, and took time to explain the dreadful zombie file that, I have the feeling, only the syslog-ng, revamped in strange ways, could have induced: (same title) http://forums.gentoo.org/viewtopic-t-1001994.html#7673948 I have the same issue. My observations are: * the problems started when I upgraded from syslog-ng v3.4.8 to v3.6.2 * the 'wrong' timestamp only occurs in lines with "kernel:", not in any other (bluetoothd, su, cron, etc.) * the problem shows in /var/log/messages and other logs showing the kernel messages * the time offset is reset to a few seconds after a reboot * the time offset increases in jumps whenever my laptop sleeps; the jump size is equal to the sleep time * in other words, after waking up, most system messages have a label that is <sleep time> later, while the "kernel:" lines continue a few seconds "later" * it seems that the kernel lines print a timestamp based on the 'waking time' since boot * since my laptop usually sleeps at night and isn't rebooted very often, the current timestamp difference between "kernel:" and other lines amounts to about 14 days * upgrading the kernel (from 3.16.5 to 3.18.9) didn't change anything * after downgrading to syslog-ng v3.4.8 and restarting it, the problem went away * also, /var/log/messages was flushed with ~3000 kernel-message lines at that moment * after upgrading again to syslog-ng v3.6.2 and restarting it, the problem immediately came back, with the same offset of ~14 days All this suggests that the issue is caused by a change between syslog-ng v3.4.8 and v3.6.2, perhaps in the way the timestamp is constructed for the kernel messages. I posted the same information here, at an open bug report: https://github.com/balabit/syslog-ng/issues/121 New content in: Syslog-ng from Delay Logging to BrokenPipe/no Logging https://forums.gentoo.org/viewtopic-t-1001994.html#7777100 (all is there, busy elsewhere, sorry!) FYI, the bug was fixed upstream a little while ago. Version 3.6.3 already incorporates the fix but needs to be stabilized. Upstream bug: https://github.com/balabit/syslog-ng/issues/121 The issue has not gone away, or at least in some parts, apparently. Pls. see more detailed report (because I thought it was a grsecurity issue) at: exec_logging (and more) not working http://forums.grsecurity.net/viewtopic.php?f=3&t=4308 I also opened a bug with syslog-ng devs: some logging stops working https://github.com/balabit/syslog-ng/issues/766 Cheers! It seems that kernel log timestamps are fine in syslog-ng-3.6.4 but broken again in 3.7.1 (In reply to aditsu from comment #13) > It seems that kernel log timestamps are fine in syslog-ng-3.6.4 but broken > again in 3.7.1 confirmed - damn, while investigating [1] I realized this : tor-relay log # grep SYN *log kern.log:Nov 20 22:26:29 tor-relay kernel: [2431358.124515] TCP: request_sock_TCP: Possible SYN flooding on port 80. Sending cookies. Check SNMP counters. syslog:Nov 20 22:02:34 tor-relay kernel: TCP: request_sock_TCP: Possible SYN flooding on port 80. Sending cookies. Check SNMP counters. *grmpf* [1] http://www.zwiebeltoralf.de/torserver/ddos/index.html syslog-ng-3.7.2 (now stable) also has the same problem. 2.7.3 fixed it eventually (really) |