Read the statement by Michael Teeuw here.
Autostarts but doesn't run, will run on restart
-
What’s the goal?
I have .config/chromium and .config/Electron with the latter being two years old and the former having a current date (I switched to Chromium because Electron was a ton of trouble).
This is all on Bullseye which I upgraded to (yeah, yeah, I know… don’t upgrade, fresh install, not supported, etc.). Up to that point, it was on Buster and ran fine.
Incidentally… I have an automated routine to bring the RPi down gracefully based on a virtual switch setting on a home automation controller. Here’s the gist:
- Set the virtual switch to “on”
- Every five minutes, the RPi queries the status of the switch
- If the switch is set to “1” (on), it launches a script with sudo
The script does the following:
- Using cec-client, it puts the Soundbar into Standby (off)
- Using cec-client, it puts the TV into standby (off)
- Sets the status of the virtual switch to “1” (on) to ensure that any other items that trigger of the state change of that switch will run as well
- Sets the status of the virtual switch to “0” (off)
- Sends an IFTTT message using WebHooks / curl
- Does a “shutdown now”
If I comment out the cec commands, it starts up incorrectly. If I manually just do a “shutdown now” and boot it back up, it starts up incorrectly.
-
@ember1205 what pi?
if armv6l, use the legacy buster image… do NOT upgrade to bullseye
uname -a will show u
the deletes were to wipe out any saved config data for the browser so it would come up clean…
(not desktop.) supposedly -
armv71
I’ve modified my shutdown control to stop MM, wipe the .config/chromium directory, and then power off. This allows chromium to load the correct information when it does finally launch.
There still remains an issue, however, with the run-start.sh script actually launching the chromium browser on boot. The log file basically ends with “0|mm | Ready to go! Please point your browser to: http://0.0.0.0:8080” on boot up. “pm2 restart mm” correctly brings everything up every time.
Here’s what the log looks like when it boots:
0|mm | > magicmirror@2.13.0 start 0|mm | > ./run-start.sh 0|mm | 0|mm | [2022-05-10 14:30:59.191] [LOG] Starting MagicMirror: v2.13.0 0|mm | [2022-05-10 14:30:59.207] [LOG] Loading config ... 0|mm | [2022-05-10 14:30:59.222] [LOG] Loading module helpers ... 0|mm | [2022-05-10 14:31:00.614] [LOG] Initializing new module helper ... 0|mm | [2022-05-10 14:31:00.617] [LOG] Module helper loaded: MMM-ImagesPhotos 0|mm | [2022-05-10 14:31:00.625] [LOG] No helper found for module: alert. 0|mm | [2022-05-10 14:31:00.733] [LOG] Initializing new module helper ... 0|mm | [2022-05-10 14:31:00.735] [LOG] Module helper loaded: updatenotification 0|mm | [2022-05-10 14:31:00.741] [LOG] No helper found for module: clock. 0|mm | [2022-05-10 14:31:01.058] [LOG] Initializing new module helper ... 0|mm | [2022-05-10 14:31:01.060] [LOG] Module helper loaded: calendar 0|mm | [2022-05-10 14:31:01.068] [LOG] No helper found for module: currentweather. 0|mm | [2022-05-10 14:31:01.072] [LOG] No helper found for module: weatherforecast. 0|mm | [2022-05-10 14:31:01.074] [LOG] All module helpers loaded. 0|mm | [2022-05-10 14:31:02.616] [LOG] Starting server on port 8080 ... 0|mm | [2022-05-10 14:31:02.665] [LOG] Server started ... 0|mm | [2022-05-10 14:31:02.680] [LOG] Connecting socket for: MMM-ImagesPhotos 0|mm | [2022-05-10 14:31:02.683] [LOG] Starting node helper for: MMM-ImagesPhotos 0|mm | [2022-05-10 14:31:02.685] [LOG] Connecting socket for: updatenotification 0|mm | [2022-05-10 14:31:02.693] [LOG] Connecting socket for: calendar 0|mm | [2022-05-10 14:31:02.700] [LOG] Starting node helper for: calendar 0|mm | [2022-05-10 14:31:02.702] [LOG] Sockets connected & modules started ... 0|mm | [2022-05-10 14:31:02.704] [LOG] 0|mm | Ready to go! Please point your browser to: http://0.0.0.0:8080
-
@ember1205 ok,
lets edit run-start.sh t- enable some more debugging
in the 1st line add -x to the change the 1st line to
#!/bin/bash -x
then pm2 flush
then do the reboot which causes mm not to come up.then pm2 logs --lines=100
the debug output will come out in the error listing of the two listings displayed
-
Full logs…
[TAILING] Tailing last 100 lines for [all] processes (change the value with --lines option) /home/pi/.pm2/pm2.log last 100 lines: PM2 | 2022-05-10T15:00:25: PM2 log: PM2 successfully stopped PM2 | 2022-05-10T15:00:44: PM2 log: =============================================================================== PM2 | 2022-05-10T15:00:44: PM2 log: --- New PM2 Daemon started ---------------------------------------------------- PM2 | 2022-05-10T15:00:44: PM2 log: Time : Tue May 10 2022 15:00:44 GMT-0400 (Eastern Daylight Time) PM2 | 2022-05-10T15:00:44: PM2 log: PM2 version : 4.4.1 PM2 | 2022-05-10T15:00:44: PM2 log: Node.js version : 16.15.0 PM2 | 2022-05-10T15:00:44: PM2 log: Current arch : arm PM2 | 2022-05-10T15:00:44: PM2 log: PM2 home : /home/pi/.pm2 PM2 | 2022-05-10T15:00:44: PM2 log: PM2 PID file : /home/pi/.pm2/pm2.pid PM2 | 2022-05-10T15:00:44: PM2 log: RPC socket file : /home/pi/.pm2/rpc.sock PM2 | 2022-05-10T15:00:44: PM2 log: BUS socket file : /home/pi/.pm2/pub.sock PM2 | 2022-05-10T15:00:44: PM2 log: Application log path : /home/pi/.pm2/logs PM2 | 2022-05-10T15:00:44: PM2 log: Worker Interval : 30000 PM2 | 2022-05-10T15:00:44: PM2 log: Process dump file : /home/pi/.pm2/dump.pm2 PM2 | 2022-05-10T15:00:44: PM2 log: Concurrent actions : 2 PM2 | 2022-05-10T15:00:44: PM2 log: SIGTERM timeout : 1600 PM2 | 2022-05-10T15:00:44: PM2 log: =============================================================================== PM2 | 2022-05-10T15:00:45: PM2 log: App [mm:0] starting in -fork mode- PM2 | 2022-05-10T15:00:45: PM2 log: App [mm:0] online /home/pi/.pm2/logs/mm-error.log last 100 lines: 0|mm | + '[' -f ./untrack-css.sh ']' 0|mm | + grep docker /proc/1/cgroup -qa 0|mm | + '[' -z :0 ']' 0|mm | ++ uname -m 0|mm | + arch=armv7l 0|mm | + false=false 0|mm | ++ grep -v '^[[:blank:]]*//' config/config.js 0|mm | ++ grep -i serveronly: 0|mm | ++ awk -F: '{print tolower($2)}' 0|mm | ++ sed -e 's/^[[:space:]]*//' 0|mm | ++ tr -d ',"'\''\r' 0|mm | + serveronly=local 0|mm | + serveronly=local 0|mm | ++ pgrep Xorg 0|mm | + xorg= 0|mm | + '[' . == . ']' 0|mm | ++ pgrep X 0|mm | + xorg= 0|mm | ++ uname 0|mm | + mac=Linux 0|mm | + '[' local. '!=' false. -o armv7l == armv6l ']' 0|mm | + '[' local. == true. ']' 0|mm | + '[' . == . -a Linux '!=' Darwin ']' 0|mm | + node serveronly /home/pi/.pm2/logs/mm-out.log last 100 lines: 0|mm | 0|mm | > magicmirror@2.13.0 start 0|mm | > ./run-start.sh 0|mm | 0|mm | [2022-05-10 15:00:55.768] [LOG] Starting MagicMirror: v2.13.0 0|mm | [2022-05-10 15:00:55.790] [LOG] Loading config ... 0|mm | [2022-05-10 15:00:55.804] [LOG] Loading module helpers ... 0|mm | [2022-05-10 15:00:57.248] [LOG] Initializing new module helper ... 0|mm | [2022-05-10 15:00:57.252] [LOG] Module helper loaded: MMM-ImagesPhotos 0|mm | [2022-05-10 15:00:57.264] [LOG] No helper found for module: alert. 0|mm | [2022-05-10 15:00:57.385] [LOG] Initializing new module helper ... 0|mm | [2022-05-10 15:00:57.387] [LOG] Module helper loaded: updatenotification 0|mm | [2022-05-10 15:00:57.391] [LOG] No helper found for module: clock. 0|mm | [2022-05-10 15:00:57.686] [LOG] Initializing new module helper ... 0|mm | [2022-05-10 15:00:57.689] [LOG] Module helper loaded: calendar 0|mm | [2022-05-10 15:00:57.692] [LOG] No helper found for module: currentweather. 0|mm | [2022-05-10 15:00:57.696] [LOG] No helper found for module: weatherforecast. 0|mm | [2022-05-10 15:00:57.698] [LOG] All module helpers loaded. 0|mm | [2022-05-10 15:01:00.465] [LOG] Starting server on port 8080 ... 0|mm | [2022-05-10 15:01:00.504] [LOG] Server started ... 0|mm | [2022-05-10 15:01:00.507] [LOG] Connecting socket for: MMM-ImagesPhotos 0|mm | [2022-05-10 15:01:00.509] [LOG] Starting node helper for: MMM-ImagesPhotos 0|mm | [2022-05-10 15:01:00.511] [LOG] Connecting socket for: updatenotification 0|mm | [2022-05-10 15:01:00.514] [LOG] Connecting socket for: calendar 0|mm | [2022-05-10 15:01:00.516] [LOG] Starting node helper for: calendar 0|mm | [2022-05-10 15:01:00.517] [LOG] Sockets connected & modules started ... 0|mm | [2022-05-10 15:01:00.519] [LOG] 0|mm | Ready to go! Please point your browser to: http://0.0.0.0:8080
-
Here’s a portion of the log when doing a stop and a start (without reboot):
0|mm | + false=false 0|mm | ++ grep -v '^[[:blank:]]*//' config/config.js 0|mm | ++ grep -i serveronly: 0|mm | ++ awk -F: '{print tolower($2)}' 0|mm | ++ sed -e 's/^[[:space:]]*//' 0|mm | ++ tr -d ',"'\''\r' 0|mm | + serveronly=local 0|mm | + serveronly=local 0|mm | ++ pgrep Xorg 0|mm | + xorg=755 0|mm | + '[' 755. == . ']' 0|mm | ++ uname 0|mm | + mac=Linux 0|mm | + '[' local. '!=' false. -o armv7l == armv6l ']' 0|mm | + '[' local. == true. ']' 0|mm | + '[' 755. == . -a Linux '!=' Darwin ']' 0|mm | + exec 0|mm | + read line 0|mm | ++ node serveronly 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:14:59.203]' '[LOG]' Starting MagicMirror: v2.13.0 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:14:59.220]' '[LOG]' Loading config ... 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:14:59.231]' '[LOG]' Loading module helpers ... 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:14:59.936]' '[LOG]' Initializing new module helper ... 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:14:59.938]' '[LOG]' Module helper loaded: MMM-ImagesPhotos 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:14:59.943]' '[LOG]' No helper found for module: alert. 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:15:00.042]' '[LOG]' Initializing new module helper ... 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:15:00.050]' '[LOG]' Module helper loaded: updatenotification 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:15:00.059]' '[LOG]' No helper found for module: clock. 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:15:00.274]' '[LOG]' Initializing new module helper ... 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:15:00.278]' '[LOG]' Module helper loaded: calendar 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:15:00.280]' '[LOG]' No helper found for module: currentweather. 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:15:00.282]' '[LOG]' No helper found for module: weatherforecast. 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:15:00.284]' '[LOG]' All module helpers loaded. 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:15:00.471]' '[LOG]' Starting server on port 8080 ... 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:15:00.496]' '[LOG]' Server started ... 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:15:00.498]' '[LOG]' Connecting socket for: MMM-ImagesPhotos 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:15:00.500]' '[LOG]' Starting node helper for: MMM-ImagesPhotos 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:15:00.502]' '[LOG]' Connecting socket for: updatenotification 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:15:00.504]' '[LOG]' Connecting socket for: calendar 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:15:00.505]' '[LOG]' Starting node helper for: calendar 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:15:00.506]' '[LOG]' Sockets connected '&' modules started ... 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo '[2022-05-10' '15:15:00.507]' '[LOG]' 0|mm | + read line 0|mm | + case "$line" in 0|mm | + echo Ready to 'go!' Please point your browser to: http://0.0.0.0:8080 0|mm | + break 0|mm | ++ echo Ready to 'go!' Please point your browser to: http://0.0.0.0:8080 0|mm | ++ awk -F: '{print $4}' 0|mm | + port=8080 0|mm | + echo 'Starting chromium browser now, have patience, it takes a minute' 0|mm | + '[' Linux '!=' Darwin ']' 0|mm | + tee 0|mm | ++ which chromium-browser 0|mm | + '[' /usr/bin/chromium-browser '!=' '' ']' 0|mm | + chromium-browser -noerrdialogs -kiosk -start_maximized --disable-infobars --app=http://localhost:8080 --ignore-certificate-errors-spki-list --ignore-ssl-errors --ignore-certificate-errors
-
I’m seeing a discrepancy where on boot it’s collecting xorg= blank versus xorg=755 on a stop/start after boot.
-
@ember1205 yes… I see that too…
-
It almost seems like the X desktop isn’t fully initialized when the pgrep command executes and it isn’t collecting info on the process as a result. The restart NEVER happens until X is fully initialized which means that it -can- collect info on the process from a restart or stop/start.
-
@ember1205 yes. I am looking for a resolution…