syslog-ng: Time zone information is incorrect on the wire

jeffsf commented 2 years ago

Maintainer: @BKPepe Environment: merge-base with openwrt/master is commit 90e4c8c6e6 Date: Mon May 23 21:05:59 2022 +0200

Hardware happens to be multiple EA8300 units. Problem observed with OpenWrt, Debian, and FreeBSD log hosts.

Using syslog-ng with an expanded version of the supplied configuration that includes remote logging. Whether using the BSD-style or "modern" syslog (RFC 5424) transport, the time zone and time are inconsistent. The receiver reports what appears to be UTC time with the local time zone offset, presently -0700.

Examining the RFC 5424 packets on the wire confirms that the incorrect timestamp is present.

Looking at the packet on the wire, at 21:03:49 local time (Pacific)

<27>1 2022-05-30T04:03:49-07:00 front hostapd - - [meta sequenceId="27"] nl80211: kernel reports: key addition failed

Local date is correct

jeff@front:/etc$ date
Sun May 29 21:08:39 PDT 2022
jeff@front:/etc$ uci get system.@system[0].timezone
PST8PDT,M3.2.0,M11.1.0

To replicate:

Configure a log host that accepts RFC5424 logging
Add the following, tailored to your log host's IP address, as /etc/syslog-ng.d/d_remote.conf on the OpenWrt device

destination d_remote {
    syslog("10.11.12.13" transport(tcp));
};

log {
        source(kernel);
    source(src);
    source(net);
    destination(d_remote);
};

sudo service syslog-ng restart or similar on the OpenWrt device

Previous references:

jeffsf commented 2 years ago

It is possible that adding recv-time-zone(UTC); to either the global options section, or to specific sources will resolve this. At least looking at the logging at shutdown, the global-only approach does not look to be sufficient

2022-05-30T04:40:28.000-07:00 10.x.y.z info: procd:  - shutdown -
2022-05-29T21:40:28.000-07:00 10.x.y.z warning: kernel:  [87022.907652] ath10k_ahb a800000.wifi: peer-unmap-event: unknown peer id 1
2022-05-29T21:40:28.000-07:00 10.x.y.z warning: kernel:  [87022.907971] ath10k_ahb a800000.wifi: peer-unmap-event: unknown peer id 1
2022-05-29T21:40:28.000-07:00 10.x.y.z info: kernel:  [87022.908714] br-switch: port 8(ap5_3charm) entered disabled state
2022-05-29T21:40:28.000-07:00 10.x.y.z warning: kernel:  [87022.913505] ath10k_ahb a800000.wifi: peer-unmap-event: unknown peer id 1
2022-05-30T04:40:28.000-07:00 10.x.y.z err: hostapd:  rmdir[ctrl_interface=/var/run/hostapd]: Permission denied
2022-05-30T04:40:28.000-07:00 10.x.y.z notice: hostapd:  ap5_20paw: interface state ENABLED->DISABLED
2022-05-30T04:40:28.000-07:00 10.x.y.z notice: hostapd:  ap5_3charm: AP-DISABLED 
2022-05-30T04:40:28.000-07:00 10.x.y.z notice: hostapd:  ap5_3charm: CTRL-EVENT-TERMINATING

neheb commented 2 years ago

Also relevant: https://gitlab.nic.cz/turris/os/packages/-/issues/471

openwrt / packages

syslog-ng: Time zone information is incorrect on the wire #18633