Syslog-ng stops logging on console after system time is changed

[varunpandeyengg]

syslog-ng

Version of syslog-ng

syslog-ng 3.8.1
Installer-Version: 3.8.1
Revision: 3.8.1
Module-Directory: /usr/lib/syslog-ng/3.8
Module-Path: /usr/lib/syslog-ng/3.8
Available-Modules: syslogformat,afuser,basicfuncs,csvparser,cef,confgen,afsql,affile,afsocket,date,sdjournal,dbparser,pseudofile,json-plugin,afprog,disk-buffer,system-source,linux-kmsg-format,cryptofuncs,kvformat
Enable-Debug: off
Enable-GProf: off
Enable-Memtrace: off
Enable-IPv6: on
Enable-Spoof-Source: on
Enable-TCP-Wrapper: on
Enable-Linux-Caps: off

Platform

Debian Stretch

Steps to reproduce

After changing the system time to an older timestamp, I am observing syslog-ng 3.8.1 on debian stretch stops forwarding logs to console. Here are the steps:

1. Change the clock:

root:~# hwclock --show
2012-12-15 17:04:18.343204+0000
root:~# date
Sat Dec 15 17:05:49 UTC 2012

2. Generate Log and verify journals:

root:~# journalctl -b | grep dummy
Dec 15 17:03:29 OS process[712]: dummy msg

Configuration

@version: 3.8
@include "scl.conf"

# Syslog-ng configuration file, compatible with default Debian syslogd
# installation.

template Format {template("$YEAR-$MONTH-$DAY $HOUR:$MIN:$SEC.$MSEC $HOST $PROGRAM[$LEVEL]:  $MSG\n");};

# First, set some global options.
options { chain_hostnames(off); flush_lines(0); use_dns(no); use_fqdn(no);
          owner("root"); group("adm"); perm(0640); dir_perm(0755) ; stats_freq(0);
          bad_hostname("^gconfd$"); file-template(Format);
};

########################
# Sources
########################
# This is the default behavior of sysklogd package
# Logs may come from unix stream, but not from another machine.
#
source s_src {
       system();
       internal();
};

# If you wish to get logs from remote machine you should uncomment
# this and comment the above source line.
#
#source s_net { tcp(ip(127.0.0.1) port(1000)); };

########################
# Destinations
########################
# First some standard logfile
#
destination d_syslog { file("/var/log/syslog"); };
destination d_messages { file("/var/log/messages"); };

# The root's console.
#
destination d_console { usertty("root"); };

# Virtual console.
#
destination d_console_all { file(`tty10`); };

########################
# Filters
########################
# Here's come the filter options. With this rules, we can set which
# message go where.

filter f_dbg { level(debug); };
filter f_info { level(info); };
filter f_notice { level(notice); };
filter f_warn { level(warn); };
filter f_err { level(err); };
filter f_crit { level(crit .. emerg); };

filter f_debug { level(debug) and not facility(auth, authpriv, news, mail); };
filter f_error { level(err .. emerg) ; };
filter f_messages { level(info,notice,warn) and
                    not facility(auth,authpriv,cron,daemon,mail,news); };

filter f_auth { facility(auth, authpriv) and not filter(f_debug); };
filter f_cron { facility(cron) and not filter(f_debug); };
filter f_daemon { facility(daemon) and not filter(f_debug); };
filter f_kern { facility(kern) and not filter(f_debug); };
filter f_lpr { facility(lpr) and not filter(f_debug); };
filter f_local { facility(local0, local1, local3, local4, local5,
                        local6, local7) and not filter(f_debug); };
filter f_mail { facility(mail) and not filter(f_debug); };
filter f_news { facility(news) and not filter(f_debug); };
filter f_syslog3 { not facility(auth, authpriv, mail) and not filter(f_debug); };
filter f_user { facility(user) and not filter(f_debug); };
filter f_uucp { facility(uucp) and not filter(f_debug); };

filter f_cnews { level(notice, err, crit) and facility(news); };
filter f_cother { level(debug, info, notice, warn) or facility(daemon, mail); };

filter f_ppp { facility(local2) and not filter(f_debug); };
filter f_console { level(warn .. emerg); };

########################
# Log paths
########################
log { source(s_src); filter(f_auth); destination(d_syslog); };
log { source(s_src); filter(f_cron); destination(d_syslog); };
log { source(s_src); filter(f_daemon); destination(d_syslog); };
log { source(s_src); filter(f_kern); destination(d_messages); };
log { source(s_src); filter(f_syslog3); destination(d_syslog); };

log { source(s_src); filter(f_debug); destination(d_syslog); };
log { source(s_src); filter(f_error); destination(d_syslog); };
log { source(s_src); filter(f_messages); destination(d_messages); };

log { source(s_src); filter(f_console); destination(d_console_all); };
log { source(s_src); filter(f_crit); destination(d_console); };

log {
  source(s_src);
  filter {('${LEVEL_NUM}' <= '5' and '${FACILITY_NUM}' == '160') or ('${LEVEL_NUM}' == '7' and '${FACILITY_NUM}' == '160')};
  destination {file('/dev/console'  perm(0644)  flags(syslog-protocol)  frac-digits(6)  persist-name(dest_label_console_1) );};
};

[czanik]

A similar issue was just posted on ServerFault. The report there says, that upgrading to 3.22 did not resolve the problem:

https://serverfault.com/questions/975469/syslog-ng-freezes-doesnt-log-when-it-encounters-log-messages-with-older-time-sta/

[MrAnno]

I haven't dug into this issue, but it might be the consequence of how sd_journal_next() works:

The journal is strictly ordered by reception time, and hence advancing to the next entry guarantees that the entry then pointing to is later in time than then previous one, or has the same timestamp.

https://www.freedesktop.org/software/systemd/man/sd_journal_next.html

[gaborznagy]

Hi @varunpandeyengg,

I've gave it a try to see the problem, but didn't reproduce it so far.
I've set back the time with years as you did, restarted journald, etc. but syslog-ng was reading journald fine.

Can you help me list the exact steps you can trigger this issue, please?

[srinadh0]

I think logging stops after a system restart.

[alltilla]

I managed to reproduce the issue with VirtualBox.

Steps:

1. Create a Virtualbox machine, called "Debian 9"
2. In the VM, install syslog-ng from apt
3. Change the syslog-ng config (/etc/syslog-ng/syslog-ng.conf) to what is copied to the issue description
4. (optional) Remove the filter from the last log path, change /dev/console to /dev/tty3
5. Shut down the VM from Debian's GUI.
6. In your own machine, run the following: VBoxManage setextradata "Debian 9" "VBoxInternal/Devices/VMMDev/0/Config/GetHostTimeDisabled" 1
7. Start the VM, log in
8. Switch to tty3 (Right Ctrl + F3), and make sure, that messages are coming (you can execute while true ; do logger test ; sleep 1 ; done from the GUI terminal, and check those messages in tty3)
9. Shut down the VM
10. In your own machine, run the following: VBoxManage modifyvm "Debian 9" --biossystemtimeoffset -315360000000 (Note: the offset is relative to the physical machine)
11. Start the VM
12. Switch to tty3
13. You should see only 1 message
14. Run while true ; do logger test ; sleep 1 ; done from the GUI terminal, switch back to tty3, see, that the test messages do not arrive

I will try to find the root cause now. :)

[TaborKelly]

I encountered this on an embedded device without a realtime clock. This is sort of a known issue in journald journalctl -f doesn't work if system clock is turned back after reboot, sd-journal: find a smart way to order log lines from different boots if neither has a useful wallclock time.

Anyway, my workaround is to force journald and syslog-ng to use the old syslog interface.

1. A journald config fragment in /etc/systemd/journald.conf.d/:

[Journal]
ForwardToSyslog=yes

2. The correct source configuration in /etc/syslog-ng/syslog-ng.conf (don't use system()):

source s_local {
    unix-stream("/run/systemd/journal/syslog"); internal();
};

3. A systemd .service file that convinces system to hook it all up at /lib/systemd/system/syslog-ng.service:

[Unit]
Description=System Logger Daemon
Documentation=man:syslog-ng(8)
Conflicts=emergency.service emergency.target
Requires=syslog.socket

[Service]
Type=notify
EnvironmentFile=/etc/syslog-ng.env
ExecStart=/usr/sbin/syslog-ng -F $OTHER_OPTIONS --cfgfile $CONFIG_FILE --control $CONTROL_FILE --persist-file $PERSIST_FILE --pidfile $PID_FILE
ExecReload=/bin/kill -HUP $MAINPID
StandardOutput=journal
StandardError=journal
Restart=on-failure

[Install]
Alias=syslog.service
WantedBy=multi-user.target

Note: Alias=syslog.service is important.
Of course, set your own options in /etc/syslog-ng.env.

The downside to this approach is that jouranld forwards syslog messages in the old RFC3164 format so you will lose sub-second timestamp resolution.

[TaborKelly]

One possible solution would be to call sd_journal_add_match() and match on the current boot ID, just like journalctl -fb does. The obvious downside being that you would probably miss the very end of the journal from the last reboot, so this might deserve its own config parameter?

[bazsi]

hmm.. it seems the current boot_id is published by the kernel at /proc/sys/kernel/random/boot_id and this should be pretty simple, calling

sd_journal_add_match(journal, "_BOOT_ID=<boot_id_value>")

in fact this could make sense in a generic form, e.g. to allow specifying this and other similar filters in the systemd-journald() driver.

Care to submit a patch?
Thanks

[TaborKelly]

I took a look at your codebase and I'm not sure that I am familiar enough with it to put together a good patch. I think that ideally syslog-ng would:

1. keep track of boot_id
2. read all old items from the last boot
3. then read all old items from the current boot (and keep reading)

Of note: you want to use sd_id128_get_boot() and sd_id128_to_string() for the boot_id. The format in /proc/sys/kernel/random/boot_id is wrong.

I have attached some proof of concept code that I wrote against 3.24.1 that does "work" but doesn't read the end of the last boot or keep track of boot_id.

0001-Only-follow-current-boot.patch.gz

[bazsi]

This is probably the same issue:

https://stackoverflow.com/questions/74763257/syslog-ng-logs-not-processing-certain-logs-possibly-due-to-journal-cursor-issue

[bazsi]

@TaborKelly I'd like to create a PR based on your patch. Can you paste a "Signed-off-by: " in this issue which I can then paste into the commit message.

This is in-line with: https://developercertificate.org/ and our CONTRIBUTING guide.

thanks

[bazsi]

@juhaszviktor can you perhaps remember why the systemd-journal() source driver has a mode where we don't link against libsystemd, rather it is dlopen()-ing that library and gets access to the various symbols using dlsym()? There are two layers of wrappers to perform this and I can't get why this was needed in the first place.

This is the location what I have in mind:

syslog-ng/modules/systemd-journal/journald-subsystem.c

Line 168 in 5dddf4a

load_journald_subsystem(void)

When I tried to compile syslog-ng with this mode, it even errored out, so seemingly we are not exercising this compilation mode.

I would get rid of the entire thing if there's no plausible explanation. Thanks.

[TaborKelly]

@bazsi, you absolutely have my permission to use my code in that patch in line with the Developer Certificate of Origin Version 1.1.

Signed-off-by: Tabor Kelly taborkelly@gmail.com