As soon as I start a KVM machine the timestamp jumps back, and when I stop the machine, the timestamp is back again : Dec 22 20:39:14 t44 tfoerste[26217]: start Dec 21 23:31:12 t44 kernel: device vnet0 entered promiscuous mode Dec 21 23:31:13 t44 kernel: br0: port 4(vnet0) entered forwarding state Dec 21 23:31:13 t44 kernel: br0: port 4(vnet0) entered forwarding state Dec 21 23:31:13 t44 kernel: kvm: zapping shadow pages for mmio generation wraparound Dec 21 23:31:23 t44 kernel: kvm [26229]: vcpu0 unhandled rdmsr: 0x606 Dec 21 23:31:26 t44 kernel: br0: port 4(vnet0) entered disabled state Dec 21 23:31:26 t44 kernel: device vnet0 left promiscuous mode Dec 21 23:31:26 t44 kernel: br0: port 4(vnet0) entered disabled state Dec 22 20:39:39 t44 tfoerste[26269]: end t44 /var/lib/libvirt/images # emerge --info syslog-ng Portage 2.2.14 (python 3.3.5-final-0, hardened/linux/amd64, gcc-4.8.3, glibc-2.19-r1, 3.17.7-hardened x86_64) ================================================================= System Settings ================================================================= System uname: Linux-3.17.7-hardened-x86_64-Intel-R-_Core-TM-_i5-4300U_CPU_@_1.90GHz-with-gentoo-2.2 KiB Mem: 12033696 total, 4534448 free KiB Swap: 16777212 total, 16744964 free Timestamp of tree: Mon, 22 Dec 2014 14:45:01 +0000 ld GNU ld (Gentoo 2.24 p1.4) 2.24 app-shells/bash: 4.2_p53 dev-java/java-config: 2.2.0 dev-lang/perl: 5.18.2-r2 dev-lang/python: 2.7.7, 3.3.5-r1 dev-util/cmake: 2.8.12.2-r1 dev-util/pkgconfig: 0.28-r1 sys-apps/baselayout: 2.2 sys-apps/openrc: 0.13.6 sys-apps/sandbox: 2.6-r1 sys-devel/autoconf: 2.13, 2.69 sys-devel/automake: 1.13.4 sys-devel/binutils: 2.24-r3 sys-devel/gcc: 4.8.3 sys-devel/gcc-config: 1.7.3 sys-devel/libtool: 2.4.2-r1 sys-devel/make: 4.0-r1 sys-kernel/linux-headers: 3.16 (virtual/os-headers) sys-libs/glibc: 2.19-r1 Repositories: gentoo toralf ACCEPT_KEYWORDS="amd64" ACCEPT_LICENSE="*" CBUILD="x86_64-pc-linux-gnu" CFLAGS="-O2 -pipe -march=native" CHOST="x86_64-pc-linux-gnu" CONFIG_PROTECT="/etc /usr/share/config /usr/share/gnupg/qualified.txt" CONFIG_PROTECT_MASK="/etc/ca-certificates.conf /etc/dconf /etc/env.d /etc/fonts/fonts.conf /etc/gconf /etc/gentoo-release /etc/php/apache2-php5.5/ext-active/ /etc/php/cgi-php5.5/ext-active/ /etc/php/cli-php5.5/ext-active/ /etc/revdep-rebuild /etc/sandbox.d /etc/terminfo" CXXFLAGS="-O2 -pipe -march=native" DISTDIR="/usr/portage/distfiles" EMERGE_DEFAULT_OPTS="--keep-going=y --nospinner --tree --quiet-build --deep --autounmask --autounmask-unrestricted-atoms" FCFLAGS="-O2 -pipe" FEATURES="assume-digests binpkg-logs config-protect-if-modified distlocks ebuild-locks fixlafiles merge-sync news parallel-fetch preserve-libs protect-owned sandbox sfperms strict unknown-features-warn unmerge-logs unmerge-orphans userfetch userpriv usersandbox usersync xattr" FFLAGS="-O2 -pipe" GENTOO_MIRRORS="http://mirror.netcologne.de/gentoo/ http://ftp.snt.utwente.nl/pub/os/linux/gentoo http://gentoo.mirror.dkm.cz/pub/gentoo/ http://ftp-stud.hs-esslingen.de/pub/Mirrors/gentoo/" LANG="en_US.utf8" LDFLAGS="-Wl,-O1 -Wl,--as-needed" MAKEOPTS="-j3" PKGDIR="/usr/portage/packages" PORTAGE_CONFIGROOT="/" PORTAGE_RSYNC_OPTS="--recursive --links --safe-links --perms --times --omit-dir-times --compress --force --whole-file --delete --stats --human-readable --timeout=180 --exclude=/distfiles --exclude=/local --exclude=/packages" PORTAGE_TMPDIR="/var/tmp" PORTDIR="/usr/portage" PORTDIR_OVERLAY="/usr/local/portage" SYNC="rsync://rsync.de.gentoo.org/gentoo-portage" USE="X acl aes-ni amd64 apache2 avx avx2 berkdb bzip2 cli corefonts cracklib crypt cups cxx dbus dnssec dri drmkms dvd ecc ffmpeg fontconfig fortran fpm gdbm git gtk gudev gui hardened iconv isag jpeg justify libvirtd logrotate macvtap mbox mmx modules multilib mysql ncurses nls nptl ogg opengl openmp pam pax_kernel pcre plasma png policykit qemu qt3support qt4 readline session spice sse sse2 sse4 sse4_1 sse4_2 ssh-askpass ssl ssse3 tcpd theora thinkpad threads tk tls truetype uml unicode urandom usb usbredir uxa v4l v4l2 vaapi video vorbis xa xattr xmp xscreensaver xtpax xvfb xvmc zlib" ABI_X86="64" ALSA_CARDS="hda-intel" APACHE2_MODULES="authn_core authz_core socache_shmcb unixd actions alias auth_basic authn_alias authn_anon authn_dbm authn_default authn_file authz_dbm authz_default authz_groupfile authz_host authz_owner authz_user autoindex cache cgi cgid dav dav_fs dav_lock deflate dir disk_cache env expires ext_filter file_cache filter headers include info log_config logio mem_cache mime mime_magic negotiation rewrite setenvif speling status unique_id userdir usertrack vhost_alias" CALLIGRA_FEATURES="kexi words flow plan sheets stage tables krita karbon braindump author" CAMERAS="ptp2" COLLECTD_PLUGINS="df interface irq load memory rrdtool swap syslog" ELIBC="glibc" GPSD_PROTOCOLS="ashtech aivdm earthmate evermore fv18 garmin garmintxt gpsclock itrax mtk3301 nmea ntrip navcom oceanserver oldstyle oncore rtcm104v2 rtcm104v3 sirf superstar2 timing tsip tripmate tnt ublox ubx" INPUT_DEVICES="evdev synaptics" KERNEL="linux" LCD_DEVICES="bayrad cfontz cfontz633 glk hd44780 lb216 lcdm001 mtxorb ncurses text" LIBREOFFICE_EXTENSIONS="presenter-console presenter-minimizer" LINGUAS="en en_GB" OFFICE_IMPLEMENTATION="libreoffice" PHP_TARGETS="php5-5" PYTHON_SINGLE_TARGET="python2_7" PYTHON_TARGETS="python2_7 python3_3" QEMU_SOFTMMU_TARGETS="x86_64 i386" QEMU_USER_TARGETS="x86_64 i386" RUBY_TARGETS="ruby19 ruby20" USERLAND="GNU" VIDEO_CARDS="intel i965" XTABLES_ADDONS="quota2 psd pknock lscan length2 ipv4options ipset ipp2p iface geoip fuzzy condition tee tarpit sysrq steal rawnat logmark ipmark dhcpmac delude chaos account" Unset: CPPFLAGS, CTARGET, INSTALL_MASK, LC_ALL, PORTAGE_BUNZIP2_COMMAND, PORTAGE_COMPRESS, PORTAGE_COMPRESS_FLAGS, PORTAGE_RSYNC_EXTRA_OPTS, USE_PYTHON ================================================================= Package Settings ================================================================= app-admin/syslog-ng-3.6.2 was built with the following: USE="ssl tcpd -amqp -caps -dbi -geoip -ipv6 -json -mongodb -pacct -redis -smtp -spoof-source -systemd" ABI_X86="64"
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)
