0

this is the extract of the syslog from a Raspberry Pi. On it runs an unbound server and other network stuff.

For some time I have the problem that in "regular" intervals (about every 4 weeks) unbound crashes. The reason for this is every time that the system time of the server is completely wrong and therefore unbound can't resolve any querries.

The last time the problem occurred was today at 12:52. When I went to examine /var/log/syslog in the course of troubleshooting, I found the following, at the exact time the error occurred.

Jan  9 12:39:00 network-pi systemd[1]: Starting Clean php session files...
Jan  9 12:39:01 network-pi systemd[1]: phpsessionclean.service: Deactivated successfully.
Jan  9 12:39:01 network-pi systemd[1]: Finished Clean php session files.
Jan  9 12:39:01 network-pi CRON[299220]: (root) CMD (  [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
Jan  9 12:40:06 network-pi kernel: [1432175.273054] [UFW BLOCK] IN=eth0 OUT= MAC=01:00:5e:00:00:01:dc:39:6f:17:44:b0:08:00 SRC=192.168.28.1 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0xC0 TTL=1 ID=33680 DF PROTO=2 
Jan  9 12:41:37 network-pi grafana-server[797]: logger=cleanup t=2023-01-09T12:41:37.334784428+01:00 level=info msg="Completed cleanup jobs" duration=27.254455ms
Jan  9 12:42:11 network-pi kernel: [1432300.277584] [UFW BLOCK] IN=eth0 OUT= MAC=01:00:5e:00:00:01:dc:39:6f:17:44:b0:08:00 SRC=192.168.28.1 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0xC0 TTL=1 ID=44309 DF PROTO=2 
Jan  9 12:44:16 network-pi kernel: [1432425.282601] [UFW BLOCK] IN=eth0 OUT= MAC=01:00:5e:00:00:01:dc:39:6f:17:44:b0:08:00 SRC=192.168.28.1 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0xC0 TTL=1 ID=55522 DF PROTO=2 
Jan  9 12:45:28 network-pi kernel: [1432496.935646] [UFW BLOCK] IN=eth0 OUT= MAC=33:33:00:00:00:01:dc:39:6f:17:44:b0:86:dd SRC=fe80:0000:0000:0000:de39:6fff:fe17:44b0 DST=ff02:0000:0000:0000:0000:0000:0000:0001 LEN=64 TC=0 HOPLIMIT=255 FLOWLBL=111406 PROTO=UDP SPT=53805 DPT=53805 LEN=24 
Jan  9 12:46:21 network-pi kernel: [1432550.287540] [UFW BLOCK] IN=eth0 OUT= MAC=01:00:5e:00:00:01:dc:39:6f:17:44:b0:08:00 SRC=192.168.28.1 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0xC0 TTL=1 ID=62072 DF PROTO=2 
Jan  9 12:47:16 network-pi influxd-systemd-start.sh[64718]: ts=2023-01-09T11:47:16.964338Z lvl=info msg="Retention policy deletion check (start)" log_id=0e~ROKiG000 service=retention trace_id=0fHaYLP0000 op_name=retention_delete_check op_event=start
Jan  9 12:47:16 network-pi influxd-systemd-start.sh[64718]: ts=2023-01-09T11:47:16.964733Z lvl=info msg="Retention policy deletion check (end)" log_id=0e~ROKiG000 service=retention trace_id=0fHaYLP0000 op_name=retention_delete_check op_event=end op_elapsed=0.452ms
Jan  9 12:48:26 network-pi kernel: [1432675.292521] [UFW BLOCK] IN=eth0 OUT= MAC=01:00:5e:00:00:01:dc:39:6f:17:44:b0:08:00 SRC=192.168.28.1 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0xC0 TTL=1 ID=25195 DF PROTO=2 
Jan  9 12:50:31 network-pi kernel: [1432800.296900] [UFW BLOCK] IN=eth0 OUT= MAC=01:00:5e:00:00:01:dc:39:6f:17:44:b0:08:00 SRC=192.168.28.1 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0xC0 TTL=1 ID=56033 DF PROTO=2 
Jan  9 12:51:37 network-pi grafana-server[797]: logger=cleanup t=2023-01-09T12:51:37.329007025+01:00 level=info msg="Completed cleanup jobs" duration=22.2181ms
<0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00><0x00Dec 23 22:47:21 network-pi modprobe[430]: modprobe: WARNING: Module scsi_dh_alua not found in directory /lib/modules/5.15.0-1022-raspi
Dec 23 22:47:21 network-pi modprobe[430]: modprobe: WARNING: Module scsi_dh_emc not found in directory /lib/modules/5.15.0-1022-raspi
Dec 23 22:47:21 network-pi modprobe[430]: modprobe: WARNING: Module scsi_dh_rdac not found in directory /lib/modules/5.15.0-1022-raspi
Dec 23 22:47:21 network-pi systemd[1]: Mounted FUSE Control File System.
Dec 23 22:47:21 network-pi systemd[1]: Mounted Kernel Configuration File System.
Dec 23 22:47:21 network-pi kernel: [    0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd083]
Dec 23 22:47:21 network-pi kernel: [    0.000000] Linux version 5.15.0-1022-raspi (buildd@bos01-arm64-024) (gcc (Ubuntu 11.3.0-1ubuntu1~22.04) 11.3.0, GNU ld (GNU Binutils for Ubuntu) 2.38) #24-Ubuntu SMP PREEMPT Mon Dec 5 09:58:33 UTC 2022 (Ubuntu 5.15.0-1022.24-raspi 5.15.74)
Dec 23 22:47:21 network-pi kernel: [    0.000000] random: crng init done
Dec 23 22:47:21 network-pi kernel: [    0.000000] Machine model: Raspberry Pi 4 Model B Rev 1.4
Dec 23 22:47:21 network-pi kernel: [    0.000000] efi: UEFI not found.
Dec 23 22:47:21 network-pi kernel: [    0.000000] Reserved memory: created CMA memory pool at 0x0000000029000000, size 64 MiB
Dec 23 22:47:21 network-pi kernel: [    0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
Dec 23 22:47:21 network-pi kernel: [    0.000000] Zone ranges:
Dec 23 22:47:21 network-pi kernel: [    0.000000]   DMA      [mem 0x0000000000000000-0x000000003fffffff]
Dec 23 22:47:21 network-pi kernel: [    0.000000]   DMA32    [mem 0x0000000040000000-0x00000000ffffffff]
Dec 23 22:47:21 network-pi kernel: [    0.000000]   Normal   [mem 0x0000000100000000-0x00000001ffffffff]
Dec 23 22:47:21 network-pi kernel: [    0.000000] Movable zone start for each node
Dec 23 22:47:21 network-pi kernel: [    0.000000] Early memory node ranges
Dec 23 22:47:21 network-pi kernel: [    0.000000]   node   0: [mem 0x0000000000000000-0x000000003b3fffff]

To me, it looks like the Pi is rebooting for some reason without shutting down properly. Why is the restart date/time set to December 23 and a completely wrong time? Shouldn't ntpd synchronize somehow?

However, I can't do anything with this level of knowledge. how can I find out why the Pi "crashed?"? It was not due to the power supply, since it is connected to a UPS.

Improve this question
3
  • 1
    Which version are you using? The latest ?
    – harrymc
    Jan 9 at 21:03
  • WHat is the current date on the computer? Did you run some logrotate recently?
    – Romeo Ninov
    Jan 10 at 8:57
  • The stock RPi does not have a rtc, therefore has no notion of the correct time when it starts to boot. It is further ahead in the boot cycle before a correct time is ascertained and logging marks entries with the correct date & time. As to why it reboots, could be hardware failure. Did you take proper esd precautions when you built it? And no, momentarily touching metal every so often does not count.
    – Bib
    Jan 10 at 10:33

1 Answer 1

Reset to default
1

To me, it looks like the Pi is rebooting for some reason without shutting down properly.

Yes. If you pull the plug you may see much the same thing afterward.

Why is the restart date/time set to December 23 and a completely wrong time? Shouldn't ntpd synchronize somehow?

It should, but the chances of that happening before logging starts are slim to none. Until then, it uses a timestamp from the last time it was properly shutdown (which obviously this wasn't).

It was not due to the power supply, since it is connected to a UPS.

That's not really a guarantee. Power would certainly be my first guess, since there does not appear to be anything weird going on before it happens.

You could look through the logs for low voltage warnings, although that really won't confirm (or rule out) power as the issue. There isn't much you are going to be able to do beyond that as the other likely explanations are hardware failure and kernel/driver bug (least likely, but I think it can't be ruled out).

If you've retained the logs, you could look back through the previous crash events to see if there is any common element leading up to it. If this is an external problem with the power, there won't be. One possibility for this being a power problem that is caused by the Pi's activity would be if there's an external hard drive and a period of very intense use of it, causing a brown out.

The reason for this is every time that the system time of the server is completely wrong and therefore unbound can't resolve any querries.

If this is important you should delay starting the server for a few minutes after boot.

Improve this answer

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Not the answer you're looking for? Browse other questions tagged or ask your own question.