How to find reboot/shutdown cause in Buster OS?

Question

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.

Answer 1

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.

Answer 2

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.

Answer 3

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