2

My Pi is rebooting for no obvious reason. Each time it reboots, syslog has a line that says the system is rebooting, so something must be causing it. I wrote a script to log which processes are running so I can match the PID in syslog with the active tasks. I used chkconfig to set it to run at level 6 -- the reboot level, and I changed the /etc/rc6.d/K-number for my task to be sooner rather than later -- but my task is not running when the system reboots.

I considered trying to use crontab -e to run my task, but in crontab, @reboot means run when the system is starting, not when it's stopping.

How can I run my task when the system is rebooting so I can find what's causing the problem ?

Thank you in advance.

Feb 1: As requested, here's text from syslog immediately before and after one of the shutdown requests (shown by --->>>):

Jan 28 15:42:30 T-1 pppd[3569]: Using interface ppp0    
Jan 28 15:42:30 T-1 pppd[3569]: Connect: ppp0 <--> /dev/ttyUSB3    
Jan 28 15:42:30 T-1 kernel: [  155.052123] PPP BSD Compression module registered    
Jan 28 15:42:30 T-1 kernel: [  155.107169] PPP Deflate Compression module registered    
Jan 28 15:42:30 T-1 pppd[3569]: local  IP address 166.145.88.33    
Jan 28 15:42:30 T-1 pppd[3569]: remote IP address 66.174.121.64    
Jan 28 15:42:30 T-1 pppd[3569]: primary   DNS address 198.224.186.135    
Jan 28 15:42:30 T-1 pppd[3569]: secondary DNS address 198.224.187.135    
Jan 28 15:42:32 T-1 ntpd[2676]: Listen normally on 3 ppp0 166.145.88.33 UDP 123    
Jan 28 15:42:32 T-1 ntpd[2676]: peers refreshed    
Jan 28 15:42:32 T-1 ntpd_intres[2684]: DNS 0.north-america.pool.ntp.org -> 
162.210.111.4    
Jan 28 15:42:32 T-1 ntpd_intres[2684]: DNS 1.north-america.pool.ntp.org -> 129.250.35.251    
Jan 28 15:42:32 T-1 ntpd_intres[2684]: DNS 2.north-america.pool.ntp.org -> 198.55.111.50    
Jan 28 15:42:32 T-1 ntpd_intres[2684]: DNS 3.north-america.pool.ntp.org -> 206.108.0.132    
Jan 28 15:42:33 T-1 ntpd_intres[2684]: DNS 0.debian.pool.ntp.org -> 185.143.194.7    
Jan 28 15:42:33 T-1 ntpd_intres[2684]: DNS 1.debian.pool.ntp.org -> 178.33.111.49    
Jan 28 15:42:33 T-1 ntpd_intres[2684]: DNS 2.debian.pool.ntp.org -> 185.51.192.34    
Jan 28 15:42:33 T-1 ntpd_intres[2684]: DNS 3.debian.pool.ntp.org -> 162.23.41.56    
Jan 28 15:42:38 T-1 kernel: [  162.901504] tun: Universal TUN/TAP device driver, 1.6    
Jan 28 15:42:38 T-1 kernel: [  162.901520] tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>    
Jan 28 15:42:40 T-1 ntpd[2676]: Listen normally on 4 tun0 10.221.0.53 UDP 123    
Jan 28 15:42:40 T-1 ntpd[2676]: peers refreshed    
Jan 28 15:44:20 T-1 kernel: [  264.553863] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)    
Jan 28 16:17:03 T-1 kernel: [ 2227.634289] rtc rtc0: __rtc_set_alarm: err=-22    
Jan 28 16:17:09 T-1 kernel: [ 2233.700531] ip_tables: (C) 2000-2006 Netfilter Core Team    
Jan 28 16:55:32 T-1 kernel: [ 4536.916200] device wlan0 left promiscuous mode    
Jan 28 16:55:40 T-1 kernel: [ 4544.603733] device wlan0 entered promiscuous mode    
Jan 28 18:00:04 T-1 kernel: [ 8408.971851] device wlan0 left promiscuous mode    
Jan 28 18:00:12 T-1 kernel: [ 8416.412629] device wlan0 entered promiscuous mode    
Jan 28 18:33:07 T-1 kernel: [10391.538366] device wlan0 left promiscuous mode    
Jan 28 18:33:12 T-1 kernel: [10397.096754] device wlan0 entered promiscuous mode

--->>> 
Jan 28 20:13:12 T-1 shutdown[29119]: shutting down for system reboot

Jan 28 20:13:12 T-1 init: Switching to runlevel: 6    
Jan 28 20:13:20 T-1 ntpd[2676]: ntpd exiting on signal 15    
Jan 28 20:13:20 T-1 pppd[3569]: Terminating on signal 15    
Jan 28 20:13:20 T-1 pppd[3569]: Connect time 270.9 minutes.    
Jan 28 20:13:20 T-1 pppd[3569]: Sent 139485060 bytes, received 19038810 bytes.    
Jan 28 20:13:20 T-1 pppd[3569]: Connection terminated.    
Jan 28 20:13:20 T-1 kernel: [16404.301032] device wlan0 left promiscuous mode    
Jan 28 20:13:20 T-1 pppd[3569]: Terminating on signal 15
Jan 28 20:13:20 T-1 pppd[3569]: Exit.
goldilocks
  • 58,859
  • 17
  • 112
  • 227
NewtownGuy
  • 111
  • 7
  • shutdown[29119] is an actual process. I don't know if it exits immediately or not. Instead of using ps -Af, you could use ps -fC shutdown and if it is still there, you will get the parent PID. To try and match that up, have cron run a task every 5 or 15 minutes logging ps -Af to a file (you only need the latest copy). – goldilocks Feb 01 '18 at 17:23
  • I'm adding this as a comment because I can't try it right now.

    If you think shutdown is being run as a command, try renaming the shutdown binary (such as shutdown-real). Create an executable shell script named shutdown in the same directory as shutdown-real. In the script use echo or logger to report shutdown's parent pid. Something like echo "$0: pid $$, parent $PPID" ; sleep 1; shutdown-real

     – Chad Farmer Feb 01 '18 at 21:30

2 Answers2

3

I assume you are using an operating system like Raspbian since version Jessie. Then you can use a simple systemd Unit file to run a script at shutdown. Just create a new service with:

rpi ~$ sudo systemctl --force --full edit log-shutdown.service

In the empty editor insert these statements, save them and quit the editor:

[Unit]
Description=Execute script on shutdown

[Service]
RemainAfterExit=yes
ExecStop=/bin/bash -c '/bin/echo "$(/bin/date): executed this script on shutdown" >> /home/pi/shutdown.log'
# or using
#ExecStop=/full/path/to/your-script

[Install]
WantedBy=multi-user.target

Enable the new service with:

rpi ~$ sudo systemctl enable --now log-shutdown.service

After reboot you will find the file /home/pi/shutdown.log.

Ingo
  • 42,107
  • 20
  • 85
  • 197
0

Unless you are running an old version of Raspbian the concept of run levels is depreciated. The systemd equivalent to runlevel 6 would be reboot.target.

However, what you are doing should still work, except:

I changed the /etc/rc6.d/K-number for my task to be sooner rather than later

Those prefixes are S for start and K for kill; a script which is symlinked using the latter will have it's stop option called, if any. Stuff in runlevel 0 and 6 are mostly K because they are services started at boot that are now being shut down.

If you want to start something in reboot, use S.

goldilocks
  • 58,859
  • 17
  • 112
  • 227
  • I'm now using this in my file to control run levels: ### BEGIN INIT INFO

    Provides: a_run_at_shutdown

    Required-Start: hostname $local_fs

    Required-Stop:

    Should-Start:

    Default-Start: 1 2 3 4 5 6

    Default-Stop: 0

    Short-Description: Start/stop a_run_at_shutdown.

    Description: This script starts/stops a_run_at_shutdown

    END INIT INFO

    How do I get it to run first when the system reboots ? The routine does ps -Af to get the names of all tasks so I can check syslog to see which routine caused the shutdown. It's listed in run level 6 after all kills.

     – NewtownGuy Jan 31 '18 at 17:27
  • Why don't you just have it start in runlevel 6 then? The system may be considering it as already started. By the way, you should search the log for oom-killer https://en.wikipedia.org/wiki/Out_of_memory This doesn't usually trigger a reboot, but it might. – goldilocks Feb 01 '18 at 14:18
  • What I'm REALLY trying to do is find what process is causing my system to randomly shutdown and reboot so I can avoid it. In syslog, there is always: shutdown[16638]: shutting down for system reboot, or some other process number. I wrote a script to record PID's at shutdown, but it runs after shutdown has started by which time the process that caused it is gone. This is a real head-banger ! I found some people had power supply problems, but they never said syslog has a proper shutdown request. Nothing immediately precedes the shutdown. By chance, I captured PID's 20 sec before SD but nothing. – NewtownGuy Feb 01 '18 at 15:21
  • Maybe you should paste an example of the syslog output into your question, 50 lines with the "shutdown" bit in the middle or near the end. – goldilocks Feb 01 '18 at 15:29
  • HOWEVER, I am seeing this in syslog about 2 hours before reboot, at least in some of the cases: rtc rtc0: __rtc_set_alarm: err=-22. My rtc seems to be working OK, and I don't know if it can cause system reboot. – NewtownGuy Feb 01 '18 at 15:30
  • How do I enter something longer than the 500 characters that fit in this comment box ? I have the text you requested but I need about 2500 characters. – NewtownGuy Feb 01 '18 at 15:37
  • Edit into the question. – goldilocks Feb 01 '18 at 15:37
  • What formatting do I put around it ? At the moment, all the lines run together. – NewtownGuy Feb 01 '18 at 15:44
  • Select it all with the mouse then click the { } button in the bar above the entry box. This will indent it four spaces which then comes out formatted as code. There's also a ? help at the right end of the bar. – goldilocks Feb 01 '18 at 15:51
  • Thank you. I did it the hard way. It is above. I noticed that "kernel: [ 2467.360315] device wlan0 entered promiscuous mode" is often before "shutting down" but it can be anywhere from seconds to hours before, and is not always the last thing before "shutting down." – NewtownGuy Feb 01 '18 at 15:57