Odd logging times

Post new topic   Reply to topic    DD-WRT Forum Index -> Atheros WiSOC based Hardware
Goto page 1, 2  Next
Author Message
lexridge
DD-WRT Guru


Joined: 07 Jun 2006
Posts: 964
Location: WV, USA

PostPosted: Wed May 25, 2022 13:12    Post subject: Odd logging times Reply with quote
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.

Forum member #248
Sponsor
lexridge
DD-WRT Guru


Joined: 07 Jun 2006
Posts: 964
Location: WV, USA

PostPosted: Wed May 25, 2022 13:22    Post subject: Reply with quote
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.

Forum member #248
kernel-panic69
DD-WRT Guru


Joined: 08 May 2018
Posts: 14126
Location: Texas, USA

PostPosted: Wed May 25, 2022 16:45    Post subject: Reply with quote
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
the-joker
DD-WRT Developer/Maintainer


Joined: 31 Jul 2021
Posts: 2146
Location: All over YOUR webs

PostPosted: Wed May 25, 2022 17:02    Post subject: Reply with quote
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.

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?

_________________
Saving your retinas from the burn!🔥
DD-WRT Inspired themes for routers
DD-WRT Inspired themes for the phpBB Forum
DD-WRT Inspired themes for the SVN Trac & FTP site
Join in for a chat @ #style_it_themes_public:matrix.org or #style_it_themes:discord

DD-WRT UI Themes Bug Reporting and Discussion thread

Router: ANus RT-AC68U E1 (recognized as C1)
mrjcd
DD-WRT Guru


Joined: 31 Jan 2015
Posts: 6268
Location: Texas

PostPosted: Wed May 25, 2022 17:20    Post subject: Reply with quote
EA8500 r48957
logs are fine
NO funny stuff or weird time skips/changes.
good as it ever was Cool
AND
NO, she ain't been reset in long time...can't remember when Twisted Evil
lexridge
DD-WRT Guru


Joined: 07 Jun 2006
Posts: 964
Location: WV, USA

PostPosted: Wed May 25, 2022 18:49    Post subject: Reply with quote
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.

Forum member #248
lexridge
DD-WRT Guru


Joined: 07 Jun 2006
Posts: 964
Location: WV, USA

PostPosted: Wed May 25, 2022 18:53    Post subject: Reply with quote
the-joker wrote:
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.

Forum member #248
lexridge
DD-WRT Guru


Joined: 07 Jun 2006
Posts: 964
Location: WV, USA

PostPosted: Thu May 26, 2022 3:23    Post subject: Reply with quote
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.

Forum member #248
blkt
DD-WRT Guru


Joined: 20 Jan 2019
Posts: 5660

PostPosted: Thu May 26, 2022 5:45    Post subject: Reply with quote
Watch out for those pesky solar flares.
the-joker
DD-WRT Developer/Maintainer


Joined: 31 Jul 2021
Posts: 2146
Location: All over YOUR webs

PostPosted: Thu May 26, 2022 7:53    Post subject: Reply with quote
Not solar flares, that's a whole different ballgame (EMP), its cosmic particles in relation to SEU.
_________________
Saving your retinas from the burn!🔥
DD-WRT Inspired themes for routers
DD-WRT Inspired themes for the phpBB Forum
DD-WRT Inspired themes for the SVN Trac & FTP site
Join in for a chat @ #style_it_themes_public:matrix.org or #style_it_themes:discord

DD-WRT UI Themes Bug Reporting and Discussion thread

Router: ANus RT-AC68U E1 (recognized as C1)
lexridge
DD-WRT Guru


Joined: 07 Jun 2006
Posts: 964
Location: WV, USA

PostPosted: Thu May 26, 2022 12:20    Post subject: Reply with quote
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.

Forum member #248
the-joker
DD-WRT Developer/Maintainer


Joined: 31 Jul 2021
Posts: 2146
Location: All over YOUR webs

PostPosted: Thu May 26, 2022 12:37    Post subject: Reply with quote
You would have to examine the klogd implementation in dd-wrt

Im not sure if this is part of kernel, busybox or something else, a search returns https://github.com/mirror/dd-wrt/search?l=C&q=klogd

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 =)

_________________
Saving your retinas from the burn!🔥
DD-WRT Inspired themes for routers
DD-WRT Inspired themes for the phpBB Forum
DD-WRT Inspired themes for the SVN Trac & FTP site
Join in for a chat @ #style_it_themes_public:matrix.org or #style_it_themes:discord

DD-WRT UI Themes Bug Reporting and Discussion thread

Router: ANus RT-AC68U E1 (recognized as C1)


Last edited by the-joker on Thu May 26, 2022 12:44; edited 1 time in total
lexridge
DD-WRT Guru


Joined: 07 Jun 2006
Posts: 964
Location: WV, USA

PostPosted: Thu May 26, 2022 12:44    Post subject: Reply with quote
the-joker wrote:
You would have to examine the klogd implementation in dd-wrt

Im not sure if this is part of kernel, busybox or something else, a search returns https://github.com/mirror/dd-wrt/search?l=C&q=klogd

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.

Forum member #248
the-joker
DD-WRT Developer/Maintainer


Joined: 31 Jul 2021
Posts: 2146
Location: All over YOUR webs

PostPosted: Thu May 26, 2022 12:45    Post subject: Reply with quote
Yea, ignore everything, stamp nothing, dammed digital bureaucrats.

/me waves fist angrily in the air.

_________________
Saving your retinas from the burn!🔥
DD-WRT Inspired themes for routers
DD-WRT Inspired themes for the phpBB Forum
DD-WRT Inspired themes for the SVN Trac & FTP site
Join in for a chat @ #style_it_themes_public:matrix.org or #style_it_themes:discord

DD-WRT UI Themes Bug Reporting and Discussion thread

Router: ANus RT-AC68U E1 (recognized as C1)
lexridge
DD-WRT Guru


Joined: 07 Jun 2006
Posts: 964
Location: WV, USA

PostPosted: Thu May 26, 2022 12:52    Post subject: Reply with quote
the-joker wrote:
Yea, ignore everything, stamp nothing, dammed digital bureaucrats.

/me waves fist angrily in the air.


Very Happy

_________________
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.

Forum member #248
Goto page 1, 2  Next Display posts from previous:    Page 1 of 2
Post new topic   Reply to topic    DD-WRT Forum Index -> Atheros WiSOC based Hardware All times are GMT

Navigation

 
Jump to:  
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum
You cannot attach files in this forum
You cannot download files in this forum