Strange entries in syslog

[geko53]

Today I found some strange entries in my syslog. Since my last reboot (after having done a factory reset when flashing 354.27 Beta1) the router's up for some 26 hours. Nevertheless I can read the following entry in my log:

Apr 7 09:13:06 dnsmasq-dhcp[598]: DHCPINFORM(br0) 192.168.1.105 94:db:c9:xx:xx:xx
Apr 7 09:13:06 dnsmasq-dhcp[598]: DHCPACK(br0) 192.168.1.105 94:db:c9:xx:xx:xx GEKO2012
Apr 7 09:14:27 pppd[7187]: LCP terminated by peer
Apr 7 09:14:27 pppd[7187]: Connect time 1191295.3 minutes.
Apr 7 09:14:27 pppd[7187]: Sent 74256932 bytes, received 1283641698 bytes.

Uptime of my modem would have been some 2 1/2 years if I didn't make a mistake in my calculations

Another one:

Apr 6 09:20:13 dnsmasq-dhcp[598]: DHCPREQUEST(br0) 192.168.1.114 4c:25:78:xx:xx:xx
Apr 6 09:20:13 dnsmasq-dhcp[598]: DHCPACK(br0) 192.168.1.114 4c:25:78:xx:xx:xx HELUM08
Apr 6 10:29:26 rc_service: httpd 599:notify_rc restart_webdav
Apr 6 09:29:28 WEBDAV Server: daemon is stoped
Apr 6 09:29:28 start_nat_rules: apply the nat_rules(/tmp/nat_rules_ppp0__dev_ttyUSB0)!
Apr 6 09:29:29 WEBDAV server: daemon is started
Apr 6 10:32:50 dnsmasq-dhcp[598]: DHCPREQUEST(br0) 192.168.1.113 20:02:af:xx:xx:xx
Apr 6 10:32:50 dnsmasq-dhcp[598]: DHCPACK(br0) 192.168.1.113 20:02:af:xx:xx:xx SamTabGK
[...]
Apr 6 10:40:47 kernel: device wl0.1 left promiscuous mode
Apr 6 10:40:47 kernel: br0: port 4(wl0.1) entering disabled state
Apr 6 09:40:47 RT-N66U: swmode: router repeater ap
Apr 6 10:40:51 kernel: wl_module_init: passivemode set to 0x0
Apr 6 10:40:51 kernel: eth1: Broadcom BCM4331 802.11 Wireless Controller 5.110.27.20012

I don't have a satisfying explanation why timestamp suddenly is jumping back and forth again...

I've set my syslog level from 5 to 7 btw. ...

Tot kijk
Gerald

 

[DrTeeth]

Hallo,

I have had problems with the time stamp in the syslog being an hour ahead of the system time. I don't know if that is related. I had to tweak the DST settings to get them both in sync.

DrT

 

[RMerlin]

Today I found some strange entries in my syslog. Since my last reboot (after having done a factory reset when flashing 354.27 Beta1) the router's up for some 26 hours. Nevertheless I can read the following entry in my log:



Uptime of my modem would have been some 2 1/2 years if I didn't make a mistake in my calculations

Your PPPoE session was closed. This can happen if your ISP terminates the connection (for maintenance for example) or there was a temporary problem with the connection. It doesn't necessarily imply the modem was rebooted - it could have just lost sync for a minute without rebooting. Nothing really unusual there, PPPoE works just like a dialup.

 

[geko53]

Nothing really unusual there, PPPoE works just like a dialup.

Okay, but I really doubt that the shown "Connect time 1191295.3 minutes" can be true - that would sum to having been connected for 2 1/4 years

Do you have an explanation for the jumping time stamp in the other entry I've listed?

Bye
Gerald

 

[RogerSC]

I've seen that before, too, and always assumed that it had to do with how syslog messages are buffered going into the log. As long as they're correctly time-stamped, the order in the log itself doesn't matter a whole lot (other than convenience of showing the actual sequence in the log).

I suppose that you could grab the log, and sort the entries on the time (assuming that the timestamps are correct), and you would have a time sequence. On the other hand, the actual order in the log might be useful some time as well.

And I believe that the large time corrections are due to the fact that the time at boot of a linux system is pretty much always the same (in the wayback *smile*), and when ntp starts up, this is corrected to the actual time.

 

[geko53]

I suppose that you could grab the log, and sort the entries on the time (assuming that the timestamps are correct), and you would have a time sequence. On the other hand, the actual order in the log might be useful some time as well.

I do NOT believe that the cited timestamps in my log indeed are correct - in the red marked entries they jumped back for 1 hour precisely:

Apr 6 10:40:47 kernel: br0: port 4(wl0.1) entering disabled state
Apr 6 [B][COLOR="Red"]09:40:47[/COLOR][/B] RT-N66U: swmode: router repeater ap
Apr 6 10:40:51 kernel: wl_module_init: passivemode set to 0x0

That doesn't look like a question of sorting, don't you agree?

And I believe that the large time corrections are due to the fact that the time at boot of a linux system is pretty much always the same (in the wayback *smile*), and when ntp starts up, this is corrected to the actual time.

Oh, I see - the "connection time" seems to be correlated with the time disparity at the beginning of booting process - those 1191295.3 minutes really sum to the primarily shown time disparity and the amount of time that has elapsed since the correction of time disparity... Tx. very much - now I will be able to sleep peacefully

Ciao
Gerald

 

[crazyea]

maybe when your pc turned on it read DEc 31, and then the time was synced. That makes it think it was connected for 2.3 years.

Edit: has already been said.

 

[RogerSC]

I do NOT believe that the cited timestamps in my log indeed are correct - in the red marked entries they jumped back for 1 hour precisely:

Apr 6 10:40:47 kernel: br0: port 4(wl0.1) entering disabled state
Apr 6 [B][COLOR="Red"]09:40:47[/COLOR][/B] RT-N66U: swmode: router repeater ap
Apr 6 10:40:51 kernel: wl_module_init: passivemode set to 0x0

That doesn't look like a question of sorting, don't you agree?

Ciao
Gerald

I suppose that there could be two different times floating around in the router software, the daylight saving time corrected one, and the base time, and some events are using the base time stamp (like PST), and some are using the daylight saving time corrected time stamp (like PDT), but I don't have the source code downloaded to verify that.

I'm getting to the point where I'm considering downloading the source code, though, so I could look at some of these issues. And I'm real curious how the source code is structured, as well *smile*. I have some suspicions about it, but until I look, they're just guesses. Takes a lot of time though, don't know that I have it.

 

[RMerlin]

Okay, but I really doubt that the shown "Connect time 1191295.3 minutes" can be true - that would sum to having been connected for 2 1/4 years

Do you have an explanation for the jumping time stamp in the other entry I've listed?

Bye
Gerald

The time stamp is probably wrong because it started counting on December 31st - before the router could connect to an NTP server to set its clock.

No idea on the time jump change. Could be syslog that needed to be restarted to accomodate for a timezone/DST change.