Gentoo Websites Logo
Go to: Gentoo Home Documentation Forums Lists Bugs Planet Store Wiki Get Gentoo!
Bug 533328 - app-admin/syslog-ng-3.6.2: scary time stamp jumps
Summary: app-admin/syslog-ng-3.6.2: scary time stamp jumps
Status: RESOLVED UPSTREAM
Alias: None
Product: Gentoo Linux
Classification: Unclassified
Component: [OLD] Server (show other bugs)
Hardware: All Linux
: Normal normal with 2 votes (vote)
Assignee: Mr. Bones. (RETIRED)
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2014-12-22 19:41 UTC by Toralf Förster
Modified: 2016-04-07 13:12 UTC (History)
4 users (show)

See Also:
Package list:
Runtime testing required: ---


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Toralf Förster gentoo-dev 2014-12-22 19:41:34 UTC
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"
Comment 1 Jeroen Roovers gentoo-dev 2014-12-23 07:26:33 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?
Comment 2 Toralf Förster gentoo-dev 2014-12-23 17:01:42 UTC
syslog-ng3.6.1 has some obscure time jumps too (w/o any KVM) - so I expect syslog to be blamed.
Comment 3 Jeroen Roovers gentoo-dev 2014-12-23 17:39:07 UTC
Maybe you're synching time in a scary way?
Comment 4 Toralf Förster gentoo-dev 2014-12-28 12:58:09 UTC
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 ?
Comment 5 Toralf Förster gentoo-dev 2014-12-28 13:01:16 UTC
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
Comment 6 miro.rovis 2014-12-29 10:56:22 UTC
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!
Comment 7 miro.rovis 2014-12-29 13:40:15 UTC
> 
> 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!
Comment 8 miro.rovis 2015-02-09 20:49:58 UTC
> 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
Comment 9 AstroFloyd 2015-05-06 10:01:17 UTC
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
Comment 10 miro.rovis 2015-07-10 12:26:36 UTC
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!)
Comment 11 Romain Riviere 2015-07-13 13:21:11 UTC
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
Comment 12 miro.rovis 2015-11-08 15:12:34 UTC
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!
Comment 13 aditsu 2015-11-08 16:45:13 UTC
It seems that kernel log timestamps are fine in syslog-ng-3.6.4 but broken again in 3.7.1
Comment 14 Toralf Förster gentoo-dev 2015-11-22 21:22:34 UTC
(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
Comment 15 aditsu 2015-12-01 15:47:21 UTC
syslog-ng-3.7.2 (now stable) also has the same problem.
Comment 16 Toralf Förster gentoo-dev 2016-04-07 13:12:19 UTC
2.7.3 fixed it eventually (really)