0

I was analyzing my raspberry pi for reboot and its time and its cause. Earlier I was working on Jessie and I was able to understand the reboot or shutdown is normal by observing the syslog file for the pattern "exiting on signal 15.". For example on Jessie, the line will be as follows

rsyslogd: [origin software="rsyslogd" swVersion="8.4.2" x-pid="455" x-info="http://www.rsyslog.com"] exiting on signal 15.

But I upgraded my rpi to Buster OS and now I am not seeing the "signal 15" logs in the syslog. I was not able to determine the reboot cause.

How can I find the time at which the system shutdown and the time at which it boots? So that I can calculate the difference.

1
  • "Exiting on signal 15" is the normal way for a process to exit when stopped externally.
    – goldilocks
    May 26 at 14:22
0

By default rsyslog's startup messages should end up in /var/log/messages. They look like this:

 May 27 08:24:55 raspberrypi rsyslogd:  [origin software="rsyslogd" swVersion="8.1901.0" x-pid="319" x-info="https://www.rsyslog.com"] start

That's not from tomorrow ;) but by coincidence 364 days ago.

The unfortunate thing about the default config (and I am guessing a bit because I always start out with it modified) is that kernel messages go into a separate file (I like to make sure there is at least one log file that everything dumps into, which makes tracing issues etc. easier).

Rsyslog also has stop messages (eg. the "exiting on signal 15") but these are not as reliable. Also, it is sometimes (re-)started during normal operation, so not every start is during boot. However, finding that line should allow you to tell whether what precedes it is boot, and right before that stuff (it is usually pretty extensive, but sans the kernel messages will be less) will be whatever was last recorded before the system shut down or died.

Regarding rollover: Log files are by default rolled over occasionally, at points in time that are arbitrary to their content -- ie., it is not simply done at shutdown or boot, meaning there is usually continuity between them, and boot events could be anywhere in them. The rolled over files are gzipped and numbered, so eg. messages.1.gz is the most recent after messages itself.

/var/log/kern.log

This is by default where all the kernel messages go, and a good thing about them is that they include a nanosecond (seconds w/ 6 decimal places) timestamp starting at 0.000000, which is when the kernel was first loaded. Since rsyslog adds normal date-time stamps, you should be able to correspond those. Although the first bunch of messages will have a bogus time due to the Pi's lack of realtime clock, you can still correspond them as this bogus timeframe will be the same for everything.

Sometimes you can find start from kernel messages just by searching for the 0.000000 string but this is not consistent; they don't always go back that far.

0

last -x may show what you want.
last -F shows substantially the same, but with full times.

Normally boot would show time, but as the Pi has no clock this is useless.

runlevel (to lvl 5) is the first meaningful time on boot.

NOTE Even this may not give the full picture. Shortly after boot the date/time is set to last known (by fake-hwclock) before NTP is obtained, but the shutdown time should be correct.

It occurred to me that systemctl status systemd-timesyncd will show the status of timesyncd, specifically

May 27 16:31:15 MilliwaysPi3A systemd-timesyncd[314]: Synchronized to time server for the first time 27.124.125.252:123 (2.debian.pool.ntp.org).

This is effective the first time "real" time is set and is an approximation to boot time, although it may be delayed by 30 seconds.

5
  • So the shutdown time and the time at which the runlevel occurred can be used, right?
    – vishnu m c
    May 26 at 13:38
  • The last command reads the wtmp file. Whether it have all the boot from the first boot or it is limited to some days?
    – vishnu m c
    May 27 at 6:35
  • @vishnumc on my Pi4 it says wtmp begins Sat Aug 29 13:38:09 2020 and last -x reports over 500 lines.
    – Milliways
    May 27 at 6:48
  • How much we can trust the status systemd-timesyncd. My rpi was turned on 30 minutes ago but the status of timesyncd shows "Active: active (running) since Thu 2021-05-27 03:17:05 UTC; 4h 14min ago". It says that it active 4hr ago. But during that time the Rpi was off due to power failer.
    – vishnu m c
    May 27 at 7:35
  • @vishnumc This shows the time restored by fake-hwclock before NTP is obtained . The "Synchronized to time server" time should be corrected time (but may change on subsequent synch runs, I am unsure. See my other answer.
    – Milliways
    May 27 at 7:49
0

The technique suggested by Goldilocks should work, but the analysis always seemed unmanageable.

I applied this to a script I routinely use to search log files.

Basically this will show kernel logs, interspersed with systemd-timesyncd, which quite clearly shows when the system clock is changed.

May 27 15:52:30 MilliwaysPi3A kernel: [   19.976079] ICMPv6: process `dhcpcd' is using deprecated sysctl (syscall) net.ipv6.neigh.wlan0.retrans_time - use net.ipv6.neigh.wlan0.retrans_time_ms instead
May 27 16:31:15 MilliwaysPi3A systemd-timesyncd[314]: Synchronized to time server for the first time 27.124.125.252:123 (2.debian.pool.ntp.org).
May 27 16:31:48 MilliwaysPi3A kernel: [   72.887026] Bluetooth: HIDP (Human Interface Emulation) ver 1.2
#!/bin/bash
# Script to search log files for string
LOGF="//var/log/syslog" #log file to search
SRCH="kernel:|systemd-timesyncd"    # string/s to search

if [ -e $LOGF.1.gz ] || [ -e $LOGF.2.gz ]; then
    for logfile in $(ls $LOGF.*.gz | sort -rV) ; \
    do zcat $logfile | grep -E $SRCH  ; done
fi

if [ -e $LOGF.1 ]; then
    grep -E  $SRCH $LOGF.1
fi

# Include most recent
grep -E  $SRCH $LOGF
2
  • How to confirm the log was due to the reboot or systemd-timesyncd restart?
    – vishnu m c
    May 27 at 8:18
  • After all, I need to find the reboot cause also? How would you know the reboot was normal or not?
    – vishnu m c
    May 27 at 8:28

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

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