Posted: Wed May 25, 2022 13:12 Post subject: Odd logging times
I have been noticing this for quite a while now, but it's not causing any problems to my knowledge so I have largely ignored it. My log times all over the place, as if different services are using a different clock. I am running version r48897 on an EA8500. I am not seeing this on my other router running the same version (R6250).
Code:
May 25 12:50:08 gateway ntpclient[7429]: Time set from 192.168.254.15 [192.168.254.15].
May 25 12:50:08 gateway process_monitor[4650]: cyclic NTP Update success (servers 192.168.254.15)
May 25 08:51:12 gateway dnsmasq-dhcp[4106]: DHCPREQUEST(br0) 192.168.254.218 50:d4:f7:de:6d:79
May 25 08:51:12 gateway dnsmasq-dhcp[4106]: DHCPACK(br0) 192.168.254.218 50:d4:f7:de:6d:79 TP_Grge_Heater
May 25 12:53:20 gateway httpd[1944]: [httpd] : Request Error Code 408: Unexpected connection close in initial request.
May 25 09:02:04 gateway dnsmasq-dhcp[4106]: DHCPREQUEST(br0) 192.168.254.180 b0:fc:0d:b6:74:4f
May 25 09:02:04 gateway dnsmasq-dhcp[4106]: DHCPACK(br0) 192.168.254.180 b0:fc:0d:b6:74:4f amazon-9dc2d6ed0
May 25 13:09:41 gateway httpd[1944]: [httpd] : Request Error Code 408: Unexpected connection close in initial request.
Not a show stopper by any means, but can anyone explain this? _________________ Linksys EA8500 (Internet Gateway, AP/VAP) - DD-WRT r53562
Features in use: WDS-AP, Multiple VLANs, Samba, WireGuard, Entware: mqtt, mlocate
Netgear R7800 (WDS-AP, WAP, VAP) - DD-WRT r53562
Features in use: multiple VLANs over single trunk port
Linksys EA8500 WDS Station x2 - DD-WRT r53562
Netgear R6400v2 WAP, VAP 2.4ghz only w/VLANs over single trunk port.
OSes: Fedora 38, 9 RPis (2,3,4,5), 20 ESP8266s: Straight from Amiga to Linux in '94, never having owned a Windows PC.
After further research, it looks like a mixed bag of local times and GMT times. The offset would be correct anyway (GMT -4). _________________ Linksys EA8500 (Internet Gateway, AP/VAP) - DD-WRT r53562
Features in use: WDS-AP, Multiple VLANs, Samba, WireGuard, Entware: mqtt, mlocate
Netgear R7800 (WDS-AP, WAP, VAP) - DD-WRT r53562
Features in use: multiple VLANs over single trunk port
Linksys EA8500 WDS Station x2 - DD-WRT r53562
Netgear R6400v2 WAP, VAP 2.4ghz only w/VLANs over single trunk port.
OSes: Fedora 38, 9 RPis (2,3,4,5), 20 ESP8266s: Straight from Amiga to Linux in '94, never having owned a Windows PC.
Joined: 08 May 2018 Posts: 14126 Location: Texas, USA
Posted: Wed May 25, 2022 16:45 Post subject:
When was the last time you did a hard reset? I thought the syslog skews were fixed already. Possible regression. Is this via the syslog page or cat /var/log messages or tail -f /var/log/messages ? I'm not seeing this issue. _________________ "Life is but a fleeting moment, a vapor that vanishes quickly; All is vanity"
Contribute To DD-WRT Pogo - A minimal level of ability is expected and needed... DD-WRT Releases 2023 (PolitePol)
DD-WRT Releases 2023 (RSS Everything)
----------------------
Linux User #377467 counter.li.org / linuxcounter.net
Joined: 31 Jul 2021 Posts: 2146 Location: All over YOUR webs
Posted: Wed May 25, 2022 17:02 Post subject:
Let me explain a couple of things about timing in routers. After the recent NTP additions I became slightly more versed on the nature of associated details.
Consumer routers do not have a real time clock IDK if there is any high end modern ones that do, they would need a coin battery onboard for instance, only some x86/64 will have a RTC not all boards do even, so what they have instead is a software clock.
The software clock is affected by such things like high loads so the skew will be more noticeable between timestamps and NTP sync offsets to mention a few.
That said and outside of that, IMO the syslog is traditionally not the most time accurate record keeping for different services or events that may take more or less time to run its code before they log an event, even though they maybe running at the same time in memory, so I believe that this will also take it toll. But I could be wrong in my assumption. Syslog also starts its records from 1970 on any reboot it can be easily observed.
What is clear is that load matters where software clock is concerned, and whatever other external causes like mentioned the timezone offset.
But yea I agree, gremlins can happen (more often) and where low powered routers are concerned, I think these can be blamed safely, so nvram resets often clear up weirdness.
EA8500 r48957
logs are fine
NO funny stuff or weird time skips/changes.
good as it ever was
AND
NO, she ain't been reset in long time...can't remember when
Still not sure what is happening here, but I am using klogd to send the logs off to a Fedora server. This is where the problem is I believe. If I follow the log using tail -f /var/log/messages on the ea8500 itself, the times are consistent. Loading the complete log via less, they are still consistent. So it certainly has something to do with either a) The Fedora server the logs are being written too, or b) klogd has a problem. More investigation required.
Just for completeness, my garage router (R6250) is also writing logs to the Fedora server and its logs are timestamped correctly, just far less entries.
@kernel-panic69 I did a full nvram reset back in Feb or March.
@the-joker You are right that high CPU loads can cause the software clock to drift. Not sure how often DDWRT updates via NTP, but I have my own on-site NTP server so lag should never be an issue. _________________ Linksys EA8500 (Internet Gateway, AP/VAP) - DD-WRT r53562
Features in use: WDS-AP, Multiple VLANs, Samba, WireGuard, Entware: mqtt, mlocate
Netgear R7800 (WDS-AP, WAP, VAP) - DD-WRT r53562
Features in use: multiple VLANs over single trunk port
Linksys EA8500 WDS Station x2 - DD-WRT r53562
Netgear R6400v2 WAP, VAP 2.4ghz only w/VLANs over single trunk port.
OSes: Fedora 38, 9 RPis (2,3,4,5), 20 ESP8266s: Straight from Amiga to Linux in '94, never having owned a Windows PC.
On an unrelated brain fart, IDK if anyone has read up on Single Event Upsets (SEU) Ive seen them in action more times than I care to admit. Anyone else?
Had to Google this one. I had never heard of this before now. It was an interesting read for sure. Not sure I have ever witnessed this happening with any of my numerous present and past CPUs. _________________ Linksys EA8500 (Internet Gateway, AP/VAP) - DD-WRT r53562
Features in use: WDS-AP, Multiple VLANs, Samba, WireGuard, Entware: mqtt, mlocate
Netgear R7800 (WDS-AP, WAP, VAP) - DD-WRT r53562
Features in use: multiple VLANs over single trunk port
Linksys EA8500 WDS Station x2 - DD-WRT r53562
Netgear R6400v2 WAP, VAP 2.4ghz only w/VLANs over single trunk port.
OSes: Fedora 38, 9 RPis (2,3,4,5), 20 ESP8266s: Straight from Amiga to Linux in '94, never having owned a Windows PC.
So after simultaneously monitoring both the local ea8500 log, and the Fedora klogd host log for many hours, it is definitely only happening on the Fedora server.
I was also able to ascertain for certain that this router updates time via NTP once per hour.
So how do I monitor what DDWRT klogd is sending? Thinking Wireshark might be helpful. I would guess that I am one of few using klogd to send off the logs, so could be an unnoticed bug in it. More discovery would be required to nail it down. _________________ Linksys EA8500 (Internet Gateway, AP/VAP) - DD-WRT r53562
Features in use: WDS-AP, Multiple VLANs, Samba, WireGuard, Entware: mqtt, mlocate
Netgear R7800 (WDS-AP, WAP, VAP) - DD-WRT r53562
Features in use: multiple VLANs over single trunk port
Linksys EA8500 WDS Station x2 - DD-WRT r53562
Netgear R6400v2 WAP, VAP 2.4ghz only w/VLANs over single trunk port.
OSes: Fedora 38, 9 RPis (2,3,4,5), 20 ESP8266s: Straight from Amiga to Linux in '94, never having owned a Windows PC.
klogd is most certainly the culprit. Captured from wireshark:
Note this event has a timestamp.
Code:
10405 321.782657073 192.168.x.x 192.168.x.x Syslog 143 DAEMON.INFO: May 26 11:49:39 hostapd: wlan0.4: STA cc:32:e5:b9:44:a7 WPA: group key handshake completed (RSN)\n
This even does not contain any timestamp:
Code:
25732 1604.610272856 192.168.x.x 192.168.x.x HTTP 573 GET /Info.live.htm HTTP/1.1
Here is what I believe to be happening. Apparently when logs are sent via klogd from the EA8500, the Fedora server uses the timestamp, if included, which is always GMT (regardless of the timezone set in the router). However, klogd does not send a timestamp for all events; only certain events (as seen in Wireshark). So events that are NOT timestamped (such as httpd logins), Fedora adds it's own timestamp when received, which is locally GMT-4.
Whether this is by design of klogd, or DDWRT is not adding the timestamp for some events, is not clear. _________________ Linksys EA8500 (Internet Gateway, AP/VAP) - DD-WRT r53562
Features in use: WDS-AP, Multiple VLANs, Samba, WireGuard, Entware: mqtt, mlocate
Netgear R7800 (WDS-AP, WAP, VAP) - DD-WRT r53562
Features in use: multiple VLANs over single trunk port
Linksys EA8500 WDS Station x2 - DD-WRT r53562
Netgear R6400v2 WAP, VAP 2.4ghz only w/VLANs over single trunk port.
OSes: Fedora 38, 9 RPis (2,3,4,5), 20 ESP8266s: Straight from Amiga to Linux in '94, never having owned a Windows PC.
What I know is it depends on what version of klogd, but from version 1.1 klogd daemon has the ability to properly prioritize kernel messages.
So good luck with that. I have no fish in this kettle =)
Really not worth it at this point to follow up, me thinks. One possibility would be to configure rsyslog.d on the fedora machine to always ignore incoming timestamps, therefore adding its own. This might be much easier to do than any other solution. _________________ Linksys EA8500 (Internet Gateway, AP/VAP) - DD-WRT r53562
Features in use: WDS-AP, Multiple VLANs, Samba, WireGuard, Entware: mqtt, mlocate
Netgear R7800 (WDS-AP, WAP, VAP) - DD-WRT r53562
Features in use: multiple VLANs over single trunk port
Linksys EA8500 WDS Station x2 - DD-WRT r53562
Netgear R6400v2 WAP, VAP 2.4ghz only w/VLANs over single trunk port.
OSes: Fedora 38, 9 RPis (2,3,4,5), 20 ESP8266s: Straight from Amiga to Linux in '94, never having owned a Windows PC.