UNSOLVED MM Restarts on Pi4
-
This had been running fine for several months until I had to power down the Pi for a couple of minutes. Now it restarts every minute or so. Nothing unusual in the pm2 logs, but syslog shows issues with pm2. Log examples are at the bottom of this post.
Here are the machine details:
pi@raspberrypi:~ $ uname -a
Linux raspberrypi 4.19.97-v7l+ #1294 SMP Thu Jan 30 13:21:14 GMT 2020 armv7l GNU/Linuxpi@raspberrypi:~ $ free -m
total used free shared buff/cache available
Mem: 1939 243 736 196 959 1402
Swap: 99 3 96[Restart Example Logs.txt](Invalid file type. Allowed types are: .jpg, .jpeg, .png, .gif, .png, .jpg, .jpeg, .gif)I had a problem with restarts earlier in the year, but adding “–disable-gpu” to package.json corrected that. This issues is different.
Log examples:
/home/pi/.pm2/logs/MagicMirror-out.logmagicmirror@2.19.0 start
DISPLAY=“${DISPLAY:=:0}” ./node_modules/.bin/electron --disable-gpu js/electron.js[15.05.2022 09:51.06.160] [LOG] Starting MagicMirror: v2.19.0
[15.05.2022 09:51.06.169] [LOG] Loading config …
[15.05.2022 09:51.06.176] [LOG] Loading module helpers …
[15.05.2022 09:51.06.179] [LOG] No helper found for module: alert.
[15.05.2022 09:51.06.205] [LOG] Initializing new module helper …
[15.05.2022 09:51.06.207] [LOG] Module helper loaded: updatenotification
[15.05.2022 09:51.06.209] [LOG] No helper found for module: clock.
[15.05.2022 09:51.06.562] [LOG] Initializing new module helper …
[15.05.2022 09:51.06.564] [LOG] Module helper loaded: MMM-AVStock
[15.05.2022 09:51.06.724] [LOG] Initializing new module helper …
[15.05.2022 09:51.06.726] [LOG] Module helper loaded: calendar
[15.05.2022 09:51.06.728] [LOG] No helper found for module: weather.
[15.05.2022 09:51.06.750] [LOG] Initializing new module helper …
[15.05.2022 09:51.06.751] [LOG] Module helper loaded: newsfeed
[15.05.2022 09:51.06.751] [LOG] All module helpers loaded.
[15.05.2022 09:51.06.845] [LOG] Starting server on port 8080 …
[15.05.2022 09:51.06.861] [LOG] Server started …
[15.05.2022 09:51.06.863] [LOG] Connecting socket for: updatenotification
[15.05.2022 09:51.06.864] [LOG] Starting module helper: updatenotification
[15.05.2022 09:51.06.865] [LOG] Connecting socket for: MMM-AVStock
[15.05.2022 09:51.06.866] [LOG] Connecting socket for: calendar
[15.05.2022 09:51.06.867] [LOG] Starting node helper for: calendar
[15.05.2022 09:51.06.868] [LOG] Connecting socket for: newsfeed
[15.05.2022 09:51.06.868] [LOG] Starting node helper for: newsfeed
[15.05.2022 09:51.06.869] [LOG] Sockets connected & modules started …
[15.05.2022 09:51.07.189] [LOG] Launching application.
[15.05.2022 09:51.10.622] [LOG] [AVSTOCK] Initialized.
[15.05.2022 09:51.10.648] [LOG] Create new calendarfetcher for url: https://calendar.google.com/calendar/ical/xxxx - Interval: 300000
[15.05.2022 09:51.10.702] [LOG] Create new calendarfetcher for url: https://calendar.google.com/calendar/ical/xxxx - Interval: 300000
[15.05.2022 09:51.10.717] [LOG] Create new calendarfetcher for url: https://calendar.google.com/calendar/ical/xxxx - Interval: 300000
[15.05.2022 09:51.10.733] [LOG] Create new newsfetcher for url: http://www.nytimes.com/services/xml/rss/nyt/HomePage.xml - Interval: 300000
[15.05.2022 09:51.10.749] [LOG] Create new newsfetcher for url: https://www.reddit.com/r/nashville/.rss?format=xml - Interval: 300000
[15.05.2022 09:51.10.759] [LOG] Create new newsfetcher for url: https://rss.bizjournals.com/feed/xxxx- Interval: 300000
[15.05.2022 09:51.10.766] [INFO] Checking git for module: MMM-AVStock
[15.05.2022 09:51.10.827] [INFO] Checking git for module: default
[15.05.2022 09:51.11.535] [INFO] Newsfeed-Fetcher: Broadcasting 27 items.
[15.05.2022 09:51.11.614] [INFO] Newsfeed-Fetcher: Broadcasting 19 items.
[15.05.2022 09:51.12.064] [INFO] Calendar-Fetcher: Broadcasting 3 events.
[15.05.2022 09:51.12.456] [INFO] Newsfeed-Fetcher: Broadcasting 32 items.
[15.05.2022 09:51.12.562] [INFO] Calendar-Fetcher: Broadcasting 5 events.
[15.05.2022 09:51.13.815] [INFO] Calendar-Fetcher: Broadcasting 11 events.magicmirror@2.19.0 start
DISPLAY=“${DISPLAY:=:0}” ./node_modules/.bin/electron --disable-gpu js/electron.js[15.05.2022 09:51.49.060] [LOG] Starting MagicMirror: v2.19.0
[15.05.2022 09:51.49.069] [LOG] Loading config …
[15.05.2022 09:51.49.077] [LOG] Loading module helpers …
[15.05.2022 09:51.49.080] [LOG] No helper found for module: alert.
[15.05.2022 09:51.49.104] [LOG] Initializing new module helper …
[15.05.2022 09:51.49.107] [LOG] Module helper loaded: updatenotification
[15.05.2022 09:51.49.108] [LOG] No helper found for module: clock.
[15.05.2022 09:51.49.456] [LOG] Initializing new module helper …
[15.05.2022 09:51.49.457] [LOG] Module helper loaded: MMM-AVStock
[15.05.2022 09:51.49.617] [LOG] Initializing new module helper …
[15.05.2022 09:51.49.619] [LOG] Module helper loaded: calendar
[15.05.2022 09:51.49.620] [LOG] No helper found for module: weather.
[15.05.2022 09:51.49.642] [LOG] Initializing new module helper …
[15.05.2022 09:51.49.643] [LOG] Module helper loaded: newsfeed
[15.05.2022 09:51.49.644] [LOG] All module helpers loaded.
[15.05.2022 09:51.49.736] [LOG] Starting server on port 8080 …
[15.05.2022 09:51.49.753] [LOG] Server started …
[15.05.2022 09:51.49.755] [LOG] Connecting socket for: updatenotification
[15.05.2022 09:51.49.756] [LOG] Starting module helper: updatenotification
[15.05.2022 09:51.49.757] [LOG] Connecting socket for: MMM-AVStock
[15.05.2022 09:51.49.758] [LOG] Connecting socket for: calendar
[15.05.2022 09:51.49.759] [LOG] Starting node helper for: calendar
[15.05.2022 09:51.49.760] [LOG] Connecting socket for: newsfeed
[15.05.2022 09:51.49.761] [LOG] Starting node helper for: newsfeed
[15.05.2022 09:51.49.762] [LOG] Sockets connected & modules started …
[15.05.2022 09:51.50.087] [LOG] Launching application.
[15.05.2022 09:51.53.833] [LOG] [AVSTOCK] Initialized.
[15.05.2022 09:51.53.853] [LOG] Create new calendarfetcher for url: https://calendar.google.com/calendar/ical/xxxx - Interval: 300000
[15.05.2022 09:51.53.897] [LOG] Create new calendarfetcher for url: https://calendar.google.com/calendar/ical/xxxx - Interval: 300000
[15.05.2022 09:51.53.902] [LOG] Create new calendarfetcher for url: https://calendar.google.com/calendar/ical/xxxx - Interval: 300000
[15.05.2022 09:51.53.908] [LOG] Create new newsfetcher for url: http://www.nytimes.com/services/xml/rss/nyt/HomePage.xml - Interval: 300000
[15.05.2022 09:51.53.914] [LOG] Create new newsfetcher for url: https://www.reddit.com/r/nashville/.rss?format=xml - Interval: 300000
[15.05.2022 09:51.53.919] [LOG] Create new newsfetcher for url: https://rss.bizjournals.com/feed/xxxx - Interval: 300000
[15.05.2022 09:51.53.925] [INFO] Checking git for module: MMM-AVStock
[15.05.2022 09:51.54.020] [INFO] Checking git for module: default
[15.05.2022 09:51.54.559] [INFO] Calendar-Fetcher: Broadcasting 3 events.
[15.05.2022 09:51.54.814] [INFO] Newsfeed-Fetcher: Broadcasting 27 items.
[15.05.2022 09:51.54.919] [INFO] Newsfeed-Fetcher: Broadcasting 19 items.
[15.05.2022 09:51.55.390] [INFO] Calendar-Fetcher: Broadcasting 5 events.
[15.05.2022 09:51.55.647] [INFO] Newsfeed-Fetcher: Broadcasting 32 items.
[15.05.2022 09:51.56.729] [INFO] Calendar-Fetcher: Broadcasting 11 events./home/pi/.pm2/logs/MagicMirror-error.log
[32038:0515/095107.242238:ERROR:sandbox_linux.cc(377)] InitializeSandbox() called with multiple threads in process gpu-process.
[32196:0515/095150.137653:ERROR:sandbox_linux.cc(377)] InitializeSandbox() called with multiple threads in process gpu-process.
[32342:0515/095320.859027:ERROR:sandbox_linux.cc(377)] InitializeSandbox() called with multiple threads in process gpu-process.pi@raspberrypi:~ $ tail -100 /var/log/syslog
May 15 10:14:24 raspberrypi pm2[403]: │ 0 │ MagicMirror │ default │ 2.19.0 │ fork │ N/A │ 0 │ 0 │ stopped │ 0% │ 0b │ pi │ disabled │
May 15 10:14:24 raspberrypi pm2[403]: └─────┴────────────────┴─────────────┴─────────┴─────────┴──────────┴────────┴──────┴───────────┴──────────┴──────────┴──────────┴──────────┘
May 15 10:14:24 raspberrypi systemd[1]: pm2-pi.service: Can’t open PID file /home/pi/.pm2/pm2.pid (yet?) after start: No such file or directory
May 15 10:15:52 raspberrypi systemd[1]: pm2-pi.service: Start operation timed out. Terminating.
May 15 10:15:52 raspberrypi systemd[1]: pm2-pi.service: Failed with result ‘timeout’.
May 15 10:15:52 raspberrypi systemd[1]: Failed to start PM2 process manager.
May 15 10:15:52 raspberrypi systemd[1]: pm2-pi.service: Service RestartSec=100ms expired, scheduling restart.
May 15 10:15:52 raspberrypi systemd[1]: pm2-pi.service: Scheduled restart job, restart counter is at 3547.
May 15 10:15:52 raspberrypi systemd[1]: Stopped PM2 process manager.
May 15 10:15:52 raspberrypi systemd[1]: Starting PM2 process manager…
May 15 10:15:53 raspberrypi pm2[423]: [PM2] Spawning PM2 daemon with pm2_home=/home/pi/.pm2
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘cat’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (Usenode --trace-warnings ...to show where the warning was created)
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘cd’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘chmod’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘cp’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘dirs’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘pushd’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘popd’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘echo’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘tempdir’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘pwd’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘exec’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘ls’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘find’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘grep’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘head’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘ln’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘mkdir’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘rm’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘mv’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘sed’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘set’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘sort’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘tail’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘test’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘to’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘toEnd’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘touch’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘uniq’ of module exports inside circular dependency
May 15 10:15:53 raspberrypi pm2[423]: (node:423) Warning: Accessing non-existent property ‘which’ of module exports inside circular dependency
May 15 10:15:54 raspberrypi pm2[423]: [PM2] PM2 Successfully daemonized
May 15 10:15:54 raspberrypi pm2[423]: [PM2] Resurrecting
May 15 10:15:54 raspberrypi pm2[423]: [PM2] Restoring processes located in /home/pi/.pm2/dump.pm2
May 15 10:15:54 raspberrypi pm2[423]: [PM2] Process /home/pi/MagicMirror/installers/mm.sh restored
May 15 10:15:54 raspberrypi pm2[423]: ┌─────┬────────────────┬─────────────┬─────────┬─────────┬──────────┬────────┬──────┬───────────┬──────────┬──────────┬──────────┬──────────┐
May 15 10:15:54 raspberrypi pm2[423]: │ id │ name │ namespace │ version │ mode │ pid │ uptime │ ↺ │ status │ cpu │ mem │ user │ watching │
May 15 10:15:54 raspberrypi pm2[423]: ├─────┼────────────────┼─────────────┼─────────┼─────────┼──────────┼────────┼──────┼───────────┼──────────┼──────────┼──────────┼──────────┤
May 15 10:15:54 raspberrypi pm2[423]: │ 0 │ MagicMirror │ default │ 2.19.0 │ fork │ N/A │ 0 │ 0 │ stopped │ 0% │ 0b │ pi │ disabled │
May 15 10:15:54 raspberrypi pm2[423]: └─────┴────────────────┴─────────────┴─────────┴─────────┴──────────┴────────┴──────┴───────────┴──────────┴──────────┴──────────┴──────────┘
May 15 10:15:54 raspberrypi systemd[1]: pm2-pi.service: Can’t open PID file /home/pi/.pm2/pm2.pid (yet?) after start: No such file or directory
May 15 10:17:01 raspberrypi CRON[455]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
May 15 10:17:22 raspberrypi systemd[1]: pm2-pi.service: Start operation timed out. Terminating.
May 15 10:17:22 raspberrypi systemd[1]: pm2-pi.service: Failed with result ‘timeout’.
May 15 10:17:22 raspberrypi systemd[1]: Failed to start PM2 process manager.
May 15 10:17:22 raspberrypi systemd[1]: pm2-pi.service: Service RestartSec=100ms expired, scheduling restart.
May 15 10:17:22 raspberrypi systemd[1]: pm2-pi.service: Scheduled restart job, restart counter is at 3548.
May 15 10:17:22 raspberrypi systemd[1]: Stopped PM2 process manager.
May 15 10:17:22 raspberrypi systemd[1]: Starting PM2 process manager…
May 15 10:17:23 raspberrypi pm2[467]: [PM2] Spawning PM2 daemon with pm2_home=/home/pi/.pm2
May 15 10:17:24 raspberrypi pm2[467]: (node:467) Warning: Accessing non-existent property ‘cat’ of module exports inside circular dependency
May 15 10:17:24 raspberrypi pm2[467]: (Usenode --trace-warnings ...to show where the warning was created)
May 15 10:17:24 raspberrypi pm2[467]: (node:467) Warning: Accessing non-existent property ‘cd’ of module exports inside circular dependency
May 15 10:17:24 raspberrypi pm2[467]: (node:467) Warning: Accessing non-existent property ‘chmod’ of module exports inside circular dependency
May 15 10:17:24 raspberrypi pm2[467]: (node:467) Warning: Accessing non-existent property ‘cp’ of module exports inside circular dependency
May 15 10:17:24 raspberrypi pm2[467]: (node:467) Warning: Accessing non-existent property ‘dirs’ of module exports inside circular dependency -
@thad do
ls ~/.pm2
notice the .(dot) in front of pm2
looks like a disk corruption
how old is the SD card?
-
pi@raspberrypi:~ $ ls ~/.pm2
dump.pm2 dump.pm2.bak logs module_conf.json modules pids pm2.log pub.sock rpc.sock touchThe SD card is probably a couple of years old.
-
@thad weird…
looks like pm2 is messed up
let’s do this
pm2 delete 0to get rid of the saved task
them
pm2 unstartupit will give u a command to copy/paste on the command line. do that…
then reboot.
pm2 is gone, so nothing will start
then run the fixuppm2 script from my scripts repo
https://github.com/sdetweil/MagicMirror_scripts
see the last entry copy/paste
MagicMirror should start
then reboot to see if pm2 starts mm at boot time
-
@sdetweil
Good news, bad news…Everything worked great until the last reboot. Post reboot, the MM restarting every minute starts again.
Another observation, while running the fixuppm2 script I get those odd warnings:
Accessing non-existent property ‘pwd’ of module exports inside circular dependencySeveral months ago, January I think, you helped me with the gpu related restarting. Once we got that working I don’t think the Pi4 rebooted until last week. I have very stable power and it’s plugged into a UPS. I think this problem may have been laying dormant for a long time.
If you have other things you want me to try, let me know. For right now I have it working and I know the procedure to get it working again if I have to reboot for any reason.
-
@thad how about node -v
looks like u are on node 14.
-
pi@raspberrypi:~ $ node -v
v16.13.2
