MarkDH102
Posts: 377
Joined: Fri Feb 13, 2015 3:18 pm

Do I have a problem - looking at this bit of syslog?

Sat Nov 02, 2019 7:21 am

My Pi0 with Stretch has been doing something odd for a few months now.
My python application logs climate information and has run successfully for a number of years.
In the last few months at random times of the day (not every day), I seem to get a lockup where my data is not recorded and the CPU temp of the Pi increases by a fixed 5 degrees C for that period.
I looked at syslog for the offending period yesterday and have included an image of it.
Does anyone think that there may some sort of issue? Is the timesyncd service blocking?
My router is on permanently during the day and is only turned off when we go to bed. So from about 10:30PM to about 6AM.

https://www.dropbox.com/s/9q6d5dddeai1p ... m.jpg?dl=0

epoch1970
Posts: 4206
Joined: Thu May 05, 2016 9:33 am
Location: Paris, France

Re: Do I have a problem - looking at this bit of syslog?

Sat Nov 02, 2019 12:51 pm

This log doesn’t shed much light on what’s going on, unfortunately.

The WiFi interface doesn’t look to be able to connect properly to the AP. IP network address renewal is attempted, which in turn kicks network time sync into action. For some reason the network address doesn’t hold and the Pi tears down the configuration and tries again.
A probable reason would be that the Pi doesn’t properly connect to the underlying wireless network medium. So the IP layer above it, which doesn’t look bad in itself, gets torn down.

A generic cause would be a failing PSU. This is known to cause all sorts of seemingly random problems.

Assuming the Pi runs headless and the wireless network is encrypted, another cause would be too slow random number generation on the Pi, making wireless authentication fail. Normally Raspbian comes with the rngd service to take care of that.
"S'il n'y a pas de solution, c'est qu'il n'y a pas de problème." Les Shadoks, J. Rouxel

MarkDH102
Posts: 377
Joined: Fri Feb 13, 2015 3:18 pm

Re: Do I have a problem - looking at this bit of syslog?

Sat Nov 02, 2019 7:17 pm

Hi epoch1970

Thanks for that. I use an official Pi PSU and can see a good solid 5V on the board.
But I have now put a monitoring device on to see if it varies.

I do run headless. And for that reason, I need to run haveged (I don't know why) to produce enough randomness for VNC to work properly.
If I don't run haveged, it takes ages for VNC to grab a connection from my PC.

Image

Here is the complete syslog file for that period.

Nov 1 06:25:04 Climate-Stretch liblogging-stdlog: [origin software="rsyslogd" swVersion="8.24.0" x-pid="227" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
Nov 1 06:30:51 Climate-Stretch systemd[1]: Starting Daily apt upgrade and clean activities...
Nov 1 06:30:57 Climate-Stretch systemd[1]: Started Daily apt upgrade and clean activities.
Nov 1 06:30:57 Climate-Stretch systemd[1]: apt-daily-upgrade.timer: Adding 7min 10.488457s random time.
Nov 1 06:30:57 Climate-Stretch systemd[1]: apt-daily-upgrade.timer: Adding 12min 15.425046s random time.
Nov 1 06:52:01 Climate-Stretch CRON[4912]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.monthly ))
Nov 1 07:05:45 Climate-Stretch dhcpcd[249]: wlan0: carrier acquired
Nov 1 07:05:45 Climate-Stretch dhcpcd[249]: wlan0: IAID 38:8a:e6:b2
Nov 1 07:05:45 Climate-Stretch dhcpcd[249]: wlan0: probing address 192.168.0.60/24
Nov 1 07:05:45 Climate-Stretch dhcpcd[249]: wlan0: soliciting an IPv6 router
Nov 1 07:05:45 Climate-Stretch dhcpcd[249]: wlan0: Router Advertisement from fe80::aa0c:63ff:fe6d:3b42
Nov 1 07:05:45 Climate-Stretch dhcpcd[249]: wlan0: adding default route via fe80::aa0c:63ff:fe6d:3b42
Nov 1 07:05:51 Climate-Stretch dhcpcd[249]: wlan0: using static address 192.168.0.60/24
Nov 1 07:05:51 Climate-Stretch dhcpcd[249]: wlan0: adding route to 192.168.0.0/24
Nov 1 07:05:51 Climate-Stretch dhcpcd[249]: wlan0: adding default route via 192.168.0.1
Nov 1 07:05:51 Climate-Stretch avahi-daemon[242]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.60.
Nov 1 07:05:51 Climate-Stretch avahi-daemon[242]: New relevant interface wlan0.IPv4 for mDNS.
Nov 1 07:05:51 Climate-Stretch avahi-daemon[242]: Registering new address record for 192.168.0.60 on wlan0.IPv4.
Nov 1 07:06:23 Climate-Stretch systemd[384]: Time has been changed
Nov 1 07:06:23 Climate-Stretch systemd-timesyncd[6396]: Synchronized to time server 178.79.155.116:123 (0.debian.pool.ntp.org).
Nov 1 07:06:23 Climate-Stretch systemd[1]: Time has been changed
Nov 1 07:06:23 Climate-Stretch systemd[1]: apt-daily.timer: Adding 11h 53min 45.136795s random time.
Nov 1 07:06:23 Climate-Stretch systemd[1]: apt-daily-upgrade.timer: Adding 24min 995.498ms random time.
Nov 1 07:17:01 Climate-Stretch CRON[5880]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 1 07:43:47 Climate-Stretch vncserver-x11[298,root]: Connections: connected: 192.168.0.145::60698 (TCP)
Nov 1 07:43:49 Climate-Stretch vncserver-x11[298,root]: Connections: authenticated: 192.168.0.145::60698 (TCP), as pi (f permissions)
Nov 1 07:43:52 Climate-Stretch vncserver-x11[298,root]: SPrintConnMgr: Failed to add printer: server-error-service-unavailable
Nov 1 07:43:58 Climate-Stretch vncserver-x11[298,root]: Connections: disconnected: 192.168.0.145::60698 (TCP) ([ViewerClosed] VNC Viewer closed)
Nov 1 08:17:02 Climate-Stretch CRON[8254]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 1 09:17:01 Climate-Stretch CRON[10671]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 1 10:17:01 Climate-Stretch CRON[13026]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 1 11:17:01 Climate-Stretch CRON[15396]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 1 12:17:01 Climate-Stretch CRON[17806]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 1 12:25:52 Climate-Stretch systemd[1]: Starting Cleanup of Temporary Directories...
Nov 1 12:25:52 Climate-Stretch systemd[1]: Started Cleanup of Temporary Directories.
Nov 1 12:42:56 Climate-Stretch dhcpcd[249]: wlan0: carrier lost
Nov 1 12:42:57 Climate-Stretch dhcpcd[249]: wlan0: deleting default route via fe80::aa0c:63ff:fe6d:3b42
Nov 1 12:42:57 Climate-Stretch dhcpcd[249]: wlan0: deleting default route via 192.168.0.1
Nov 1 12:42:57 Climate-Stretch dhcpcd[249]: wlan0: deleting route to 192.168.0.0/24
Nov 1 12:42:57 Climate-Stretch avahi-daemon[242]: Withdrawing address record for 192.168.0.60 on wlan0.
Nov 1 12:42:57 Climate-Stretch avahi-daemon[242]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.60.
Nov 1 12:42:57 Climate-Stretch avahi-daemon[242]: Interface wlan0.IPv4 no longer relevant for mDNS.
Nov 1 12:43:11 Climate-Stretch dhcpcd[249]: wlan0: carrier acquired
Nov 1 12:43:11 Climate-Stretch dhcpcd[249]: wlan0: IAID 38:8a:e6:b2
Nov 1 12:43:11 Climate-Stretch dhcpcd[249]: wlan0: probing address 192.168.0.60/24
Nov 1 12:43:11 Climate-Stretch dhcpcd[249]: wlan0: soliciting an IPv6 router
Nov 1 12:43:11 Climate-Stretch dhcpcd[249]: wlan0: Router Advertisement from fe80::aa0c:63ff:fe6d:3b42
Nov 1 12:43:11 Climate-Stretch dhcpcd[249]: wlan0: adding default route via fe80::aa0c:63ff:fe6d:3b42
Nov 1 12:43:11 Climate-Stretch dhcpcd[249]: wlan0: requesting DHCPv6 information
Nov 1 12:43:16 Climate-Stretch dhcpcd[249]: wlan0: using static address 192.168.0.60/24
Nov 1 12:43:16 Climate-Stretch dhcpcd[249]: wlan0: adding route to 192.168.0.0/24
Nov 1 12:43:16 Climate-Stretch dhcpcd[249]: wlan0: adding default route via 192.168.0.1
Nov 1 12:43:16 Climate-Stretch avahi-daemon[242]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.60.
Nov 1 12:43:16 Climate-Stretch avahi-daemon[242]: New relevant interface wlan0.IPv4 for mDNS.
Nov 1 12:43:16 Climate-Stretch avahi-daemon[242]: Registering new address record for 192.168.0.60 on wlan0.IPv4.
Nov 1 13:17:01 Climate-Stretch CRON[20339]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 1 13:23:19 Climate-Stretch dhcpcd[249]: wlan0: carrier lost
Nov 1 13:23:19 Climate-Stretch systemd[1]: systemd-timesyncd.service: Watchdog timeout (limit 3min)!
Nov 1 13:23:19 Climate-Stretch systemd[1]: systemd-timesyncd.service: Killing process 6396 (systemd-timesyn) with signal SIGABRT.
Nov 1 13:23:19 Climate-Stretch systemd[1]: systemd-timesyncd.service: Main process exited, code=killed, status=6/ABRT
Nov 1 13:23:19 Climate-Stretch systemd[1]: systemd-timesyncd.service: Unit entered failed state.
Nov 1 13:23:19 Climate-Stretch systemd[1]: systemd-timesyncd.service: Failed with result 'watchdog'.
Nov 1 13:23:19 Climate-Stretch systemd[1]: systemd-timesyncd.service: Service has no hold-off time, scheduling restart.
Nov 1 13:23:19 Climate-Stretch systemd[1]: Stopped Network Time Synchronization.
Nov 1 13:23:19 Climate-Stretch systemd[1]: Starting Network Time Synchronization...
Nov 1 13:23:20 Climate-Stretch systemd[1]: Started Network Time Synchronization.
Nov 1 13:23:20 Climate-Stretch dhcpcd[249]: wlan0: deleting default route via fe80::aa0c:63ff:fe6d:3b42
Nov 1 13:23:20 Climate-Stretch dhcpcd[249]: wlan0: deleting default route via 192.168.0.1
Nov 1 13:23:20 Climate-Stretch dhcpcd[249]: wlan0: deleting route to 192.168.0.0/24
Nov 1 13:23:20 Climate-Stretch avahi-daemon[242]: Withdrawing address record for 192.168.0.60 on wlan0.
Nov 1 13:23:20 Climate-Stretch avahi-daemon[242]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.60.
Nov 1 13:23:20 Climate-Stretch avahi-daemon[242]: Interface wlan0.IPv4 no longer relevant for mDNS.
Nov 1 14:33:03 Climate-Stretch systemd[1]: systemd-logind.service: Watchdog timeout (limit 3min)!
Nov 1 14:33:03 Climate-Stretch systemd[1]: systemd-logind.service: Killing process 226 (systemd-logind) with signal SIGABRT.
Nov 1 14:33:03 Climate-Stretch systemd[1]: systemd-logind.service: Main process exited, code=killed, status=6/ABRT
Nov 1 14:33:03 Climate-Stretch systemd[1]: systemd-logind.service: Unit entered failed state.
Nov 1 14:33:03 Climate-Stretch systemd[1]: systemd-logind.service: Failed with result 'watchdog'.
Nov 1 14:33:03 Climate-Stretch systemd[1]: systemd-logind.service: Service has no hold-off time, scheduling restart.
Nov 1 14:33:03 Climate-Stretch systemd[1]: Stopped Login Service.
Nov 1 14:33:03 Climate-Stretch systemd[1]: Starting Login Service...
Nov 1 14:33:03 Climate-Stretch systemd[1]: Started Login Service.
Nov 1 14:33:11 Climate-Stretch dhcpcd[249]: wlan0: carrier acquired
Nov 1 14:33:11 Climate-Stretch dhcpcd[249]: wlan0: IAID 38:8a:e6:b2
Nov 1 14:33:11 Climate-Stretch dhcpcd[249]: wlan0: probing address 192.168.0.60/24
Nov 1 14:33:11 Climate-Stretch dhcpcd[249]: wlan0: soliciting an IPv6 router
Nov 1 14:33:12 Climate-Stretch dhcpcd[249]: wlan0: Router Advertisement from fe80::aa0c:63ff:fe6d:3b42
Nov 1 14:33:12 Climate-Stretch dhcpcd[249]: wlan0: adding default route via fe80::aa0c:63ff:fe6d:3b42
Nov 1 14:33:12 Climate-Stretch dhcpcd[249]: wlan0: requesting DHCPv6 information
Nov 1 14:33:17 Climate-Stretch dhcpcd[249]: wlan0: using static address 192.168.0.60/24
Nov 1 14:33:17 Climate-Stretch dhcpcd[249]: wlan0: adding route to 192.168.0.0/24
Nov 1 14:33:17 Climate-Stretch dhcpcd[249]: wlan0: adding default route via 192.168.0.1
Nov 1 14:33:17 Climate-Stretch avahi-daemon[242]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.60.
Nov 1 14:33:17 Climate-Stretch avahi-daemon[242]: New relevant interface wlan0.IPv4 for mDNS.
Nov 1 14:33:17 Climate-Stretch avahi-daemon[242]: Registering new address record for 192.168.0.60 on wlan0.IPv4.
Nov 1 14:33:23 Climate-Stretch systemd-timesyncd[20527]: Timed out waiting for reply from [2604:a880:800:c1::10:5001]:123 (2.debian.pool.ntp.org).
Nov 1 14:33:33 Climate-Stretch systemd-timesyncd[20527]: Timed out waiting for reply from [2a01:7e00::f03c:91ff:fe89:66e3]:123 (2.debian.pool.ntp.org).
Nov 1 14:33:44 Climate-Stretch systemd-timesyncd[20527]: Timed out waiting for reply from [2a01:7e00::f03c:91ff:fe96:f129]:123 (2.debian.pool.ntp.org).
Nov 1 14:33:54 Climate-Stretch systemd-timesyncd[20527]: Timed out waiting for reply from [2a04:92c7:e:537::96cb]:123 (2.debian.pool.ntp.org).
Nov 1 14:33:54 Climate-Stretch systemd-timesyncd[20527]: Synchronized to time server 162.159.200.123:123 (2.debian.pool.ntp.org).
Nov 1 15:17:01 Climate-Stretch CRON[22417]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 1 16:17:01 Climate-Stretch CRON[24701]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 1 17:17:01 Climate-Stretch CRON[27000]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 1 17:53:52 Climate-Stretch systemd[1]: Starting Daily apt download activities...
Nov 1 17:53:57 Climate-Stretch systemd[1]: Started Daily apt download activities.
Nov 1 17:53:58 Climate-Stretch systemd[1]: apt-daily.timer: Adding 8h 23min 44.449226s random time.
Nov 1 17:53:58 Climate-Stretch systemd[1]: apt-daily.timer: Adding 1h 16.183924s random time.
Nov 1 18:17:02 Climate-Stretch CRON[29337]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 1 19:00:52 Climate-Stretch systemd[1]: Starting Daily apt download activities...
Nov 1 19:00:58 Climate-Stretch systemd[1]: Started Daily apt download activities.
Nov 1 19:00:58 Climate-Stretch systemd[1]: apt-daily.timer: Adding 5h 6min 32.540368s random time.
Nov 1 19:00:58 Climate-Stretch systemd[1]: apt-daily.timer: Adding 8h 42min 24.659228s random time.
Nov 1 19:17:01 Climate-Stretch CRON[31683]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 1 20:17:01 Climate-Stretch CRON[1584]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 1 21:17:01 Climate-Stretch CRON[3866]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 1 21:48:27 Climate-Stretch dhcpcd[249]: wlan0: carrier lost
Nov 1 21:48:28 Climate-Stretch dhcpcd[249]: wlan0: deleting default route via fe80::aa0c:63ff:fe6d:3b42
Nov 1 21:48:28 Climate-Stretch dhcpcd[249]: wlan0: deleting default route via 192.168.0.1
Nov 1 21:48:28 Climate-Stretch dhcpcd[249]: wlan0: deleting route to 192.168.0.0/24
Nov 1 21:48:28 Climate-Stretch avahi-daemon[242]: Withdrawing address record for 192.168.0.60 on wlan0.
Nov 1 21:48:28 Climate-Stretch avahi-daemon[242]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.60.
Nov 1 21:48:28 Climate-Stretch avahi-daemon[242]: Interface wlan0.IPv4 no longer relevant for mDNS.
Nov 1 22:17:01 Climate-Stretch CRON[6123]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 1 23:17:01 Climate-Stretch CRON[8113]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 2 00:17:01 Climate-Stretch CRON[10115]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 2 01:17:01 Climate-Stretch CRON[12107]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 2 02:17:01 Climate-Stretch CRON[14098]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 2 03:17:01 Climate-Stretch CRON[16093]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 2 04:17:01 Climate-Stretch CRON[18086]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 2 05:17:01 Climate-Stretch CRON[20078]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 2 06:17:01 Climate-Stretch CRON[22074]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 2 06:24:52 Climate-Stretch systemd[1]: Starting Daily apt upgrade and clean activities...
Nov 2 06:24:58 Climate-Stretch systemd[1]: Started Daily apt upgrade and clean activities.
Nov 2 06:24:58 Climate-Stretch systemd[1]: apt-daily-upgrade.timer: Adding 55min 49.971211s random time.
Nov 2 06:24:58 Climate-Stretch systemd[1]: apt-daily-upgrade.timer: Adding 13min 54.889844s random time.
Nov 2 06:25:01 Climate-Stretch CRON[22397]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily ))

I don't see rngd running as a service though...

Best regards Mark
Attachments
Services.jpg
Services.jpg (39.88 KiB) Viewed 227 times

epoch1970
Posts: 4206
Joined: Thu May 05, 2016 9:33 am
Location: Paris, France

Re: Do I have a problem - looking at this bit of syslog?

Sat Nov 02, 2019 8:22 pm

Haveged is an alternative to rngd.
Either are used to generate random numbers in the background, for use by the OS. Cryptography loves random numbers. By default Linux uses mouse movements, keyboard key presses ... to generate random numbers. Since these devices are missing from a headless machine, a daemon working in the background, like haveged, is used instead.

Besides that. No idea what’s going on...
"S'il n'y a pas de solution, c'est qu'il n'y a pas de problème." Les Shadoks, J. Rouxel

Return to “Troubleshooting”