moodeaudio.org > Moode Forum › moOde audio player › Support v
[PROBLEM] [PROBLEM] 9.x: MPD crashing ad-hoc / stops playing

Thank you for your donation!


Cloudsmith graciously provides open-source package management and distribution for our project.


Thread Closed 
Thread Modes
Problem: [PROBLEM] 9.x: MPD crashing ad-hoc / stops playing
kurt1970 Offline
Member
*
Posts: 179
Threads: 8
Joined: Sep 2023
Reputation: 0
#21
10-18-2024, 05:48 AM (This post was last modified: 10-18-2024, 05:49 AM by kurt1970.)
Hi @Tim Curtis 

Behavior in 9.1.3 is indeed different.
Although, after a MPD crash, music doesn't come back.
Any thoughts?
Tx,
k

moodeutl log:
Code:
20241018 073617 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241018 073617 mpdmon: Buffer underrun 2 detected: Super Stereo 7
20241018 073617 mpdmon: Buffer underrun 3 detected: Super Stereo 7
20241018 073617 mpdmon: MPD restarted, play resumed
20241018 073617 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241018 073618 watchdog: Started MPD after crash detected (check system journal)
20241018 073627 watchdog: Started MPD after crash detected (check system journal)


journal fragment:
Code:
Oct 18 07:36:10 moode systemd[1]: mpd.service: State 'stop-sigterm' timed out. Killing.
Oct 18 07:36:10 moode systemd[1]: mpd.service: Killing process 13781 (mpd) with signal SIGKILL.
Oct 18 07:36:10 moode systemd[1]: mpd.service: Killing process 13790 (player) with signal SIGKILL.
Oct 18 07:36:10 moode systemd[1]: mpd.service: Main process exited, code=killed, status=9/KILL
Oct 18 07:36:10 moode systemd[1]: mpd.service: Failed with result 'timeout'.
Oct 18 07:36:10 moode systemd[1]: Stopped mpd.service - Music Player Daemon.
Oct 18 07:36:10 moode systemd[1]: mpd.service: Consumed 1.156s CPU time.
Oct 18 07:36:10 moode systemd[1]: Starting mpd.service - Music Player Daemon...
Oct 18 07:36:11 moode mpd[14128]: Ignoring the 'pid_file' setting in systemd mode
Oct 18 07:36:11 moode systemd[1]: Started mpd.service - Music Player Daemon.
Oct 18 07:36:11 moode systemd[1]: Stopping mpd.service - Music Player Daemon...
Oct 18 07:36:11 moode systemd[1]: mpd.service: Deactivated successfully.
Oct 18 07:36:11 moode systemd[1]: Stopped mpd.service - Music Player Daemon.
Oct 18 07:36:11 moode systemd[1]: Starting mpd.service - Music Player Daemon...
Oct 18 07:36:11 moode mpd[14142]: Ignoring the 'pid_file' setting in systemd mode
Oct 18 07:36:11 moode systemd[1]: Started mpd.service - Music Player Daemon.
Oct 18 07:36:12 moode systemd[1]: Stopping mpd.service - Music Player Daemon...
Oct 18 07:36:12 moode systemd[1]: mpd.service: Deactivated successfully.
Oct 18 07:36:12 moode systemd[1]: Stopped mpd.service - Music Player Daemon.
Oct 18 07:36:12 moode systemd[1]: Starting mpd.service - Music Player Daemon...
Oct 18 07:36:12 moode mpd[14156]: Ignoring the 'pid_file' setting in systemd mode
Oct 18 07:36:12 moode systemd[1]: Started mpd.service - Music Player Daemon.
Oct 18 07:36:12 moode systemd[1]: Stopping mpd.service - Music Player Daemon...
Oct 18 07:36:12 moode systemd[1]: mpd.service: Deactivated successfully.
Oct 18 07:36:12 moode systemd[1]: Stopped mpd.service - Music Player Daemon.
Oct 18 07:36:12 moode systemd[1]: Starting mpd.service - Music Player Daemon...
Oct 18 07:36:12 moode mpd[14170]: Ignoring the 'pid_file' setting in systemd mode
Oct 18 07:36:13 moode systemd[1]: Started mpd.service - Music Player Daemon.
Oct 18 07:36:13 moode systemd[1]: Stopping mpd.service - Music Player Daemon...
Oct 18 07:36:13 moode systemd[1]: mpd.service: Deactivated successfully.
Oct 18 07:36:13 moode systemd[1]: Stopped mpd.service - Music Player Daemon.
Oct 18 07:36:13 moode systemd[1]: Starting mpd.service - Music Player Daemon...
Oct 18 07:36:13 moode mpd[14187]: Ignoring the 'pid_file' setting in systemd mode
Oct 18 07:36:13 moode systemd[1]: Started mpd.service - Music Player Daemon.
Oct 18 07:36:13 moode systemd[1]: Stopping mpd.service - Music Player Daemon...
Oct 18 07:36:13 moode systemd[1]: mpd.service: Deactivated successfully.
Oct 18 07:36:13 moode systemd[1]: Stopped mpd.service - Music Player Daemon.
Oct 18 07:36:13 moode systemd[1]: mpd.service: Start request repeated too quickly.
Oct 18 07:36:13 moode systemd[1]: mpd.service: Failed with result 'start-limit-hit'.
Oct 18 07:36:13 moode systemd[1]: Failed to start mpd.service - Music Player Daemon.
Oct 18 07:36:16 moode systemd[1]: mpd.service: Start request repeated too quickly.
Oct 18 07:36:16 moode systemd[1]: mpd.service: Failed with result 'start-limit-hit'.
Oct 18 07:36:16 moode systemd[1]: Failed to start mpd.service - Music Player Daemon.
Oct 18 07:36:16 moode systemd[1]: mpd.service: Start request repeated too quickly.
Oct 18 07:36:16 moode systemd[1]: mpd.service: Failed with result 'start-limit-hit'.
Oct 18 07:36:16 moode systemd[1]: Failed to start mpd.service - Music Player Daemon.
Oct 18 07:36:17 moode systemd[1]: mpd.service: Start request repeated too quickly.
Oct 18 07:36:17 moode systemd[1]: mpd.service: Failed with result 'start-limit-hit'.
Oct 18 07:36:17 moode systemd[1]: Failed to start mpd.service - Music Player Daemon.
Oct 18 07:36:17 moode systemd[1]: mpd.service: Start request repeated too quickly.
Oct 18 07:36:17 moode systemd[1]: mpd.service: Failed with result 'start-limit-hit'.
Oct 18 07:36:17 moode systemd[1]: Failed to start mpd.service - Music Player Daemon.
Oct 18 07:36:17 moode systemd[1]: mpd.service: Start request repeated too quickly.
Oct 18 07:36:17 moode systemd[1]: mpd.service: Failed with result 'start-limit-hit'.
Oct 18 07:36:17 moode systemd[1]: Failed to start mpd.service - Music Player Daemon.
Oct 18 07:36:17 moode systemd[1]: mpd.service: Start request repeated too quickly.
Oct 18 07:36:17 moode systemd[1]: mpd.service: Failed with result 'start-limit-hit'.
Oct 18 07:36:17 moode systemd[1]: Failed to start mpd.service - Music Player Daemon.
Oct 18 07:36:18 moode systemd[1]: mpd.service: Start request repeated too quickly.
Oct 18 07:36:18 moode systemd[1]: mpd.service: Failed with result 'start-limit-hit'.
Oct 18 07:36:18 moode systemd[1]: Failed to start mpd.service - Music Player Daemon.
Oct 18 07:36:27 moode systemd[1]: Starting mpd.service - Music Player Daemon...
Oct 18 07:36:28 moode mpd[14269]: Ignoring the 'pid_file' setting in systemd mode
Oct 18 07:36:28 moode systemd[1]: Started mpd.service - Music Player Daemon.
Find
the_bertrum Offline
Senior Member+
*
Posts: 1,869
Threads: 43
Joined: Mar 2020
Reputation: 85
#22
10-18-2024, 07:17 AM
If I'm reading your log correctly, it seems you got three underrun notices, an MPD restart and another underrun right after all within a second and then MPD crashed a second later.

It looks to me like there's some other problem here that's leading to the excessive restarts. If the underruns are that frequent the station must be near un listenable anyway surely?
----------------
Robert
Find
Tim Curtis Offline
moOde audio founder
******
Posts: 13,429
Threads: 304
Joined: Mar 2018
Reputation: 545
#23
10-18-2024, 09:47 AM
Right, there is only so much that can be done to workaround stream issues.

But in any case:
1. It's possible that the MPD restart code in mpdmon.php also needs to include the code that waits for MPD to start accepting connections before trying to resume playback. I can add that code.
2. There might be some weird side effects going on between mpdmon and watchdog having to do with restarting MPD. I'd need to be able to repro the stream underruns in order to investigate that.

Whats the URL for the station?
Enjoy the Music!
moodeaudio.org | Mastodon Feed | GitHub
Website Find
Tim Curtis Offline
moOde audio founder
******
Posts: 13,429
Threads: 304
Joined: Mar 2018
Reputation: 545
#24
10-18-2024, 11:28 AM
Try this updated file that includes the "wait for MPD to start accepting connections after restart" code.

Code:
# Save original
sudo cp /var/www/daemon/mpdmon.php ./

# Install updated file
sudo wget -q https://raw.githubusercontent.com/moode-player/moode/1ec7f941f4966556715874a84f06222e49a65e4b/www/daemon/mpdmon.php -O /var/www/daemon/mpdmon.php
Enjoy the Music!
moodeaudio.org | Mastodon Feed | GitHub
Website Find
kurt1970 Offline
Member
*
Posts: 179
Threads: 8
Joined: Sep 2023
Reputation: 0
#25
10-18-2024, 11:52 AM (This post was last modified: 10-18-2024, 11:56 AM by kurt1970.)
(10-18-2024, 09:47 AM)Tim Curtis Wrote: Right, there is only so much that can be done to workaround stream issues.

But in any case:
1. It's possible that the MPD restart code in mpdmon.php also needs to include the code that waits for MPD to start accepting connections before trying to resume playback. I can add that code.
2. There might be some weird side effects going on between mpdmon and watchdog having to do with restarting MPD. I'd need to be able to repro the stream underruns in order to investigate that.

Whats the URL for the station?

1) Based on the journal log, it looks like MPD hits the max retry limit in a given time frame, and gives up.

2) The repro URL may be a challenge wrt latency, as you're in the US and I'm in Belgium. The station concerned is in Chile: http://icecast.centaury.cl:7570/SuperStereoHiRes7
If not able to repro with this, try this one: http://motherearth.streamserver24.com/li...earth.jazz
Mother Earth is nearby for me in Germany, but a little further for you. Smile
Find
kurt1970 Offline
Member
*
Posts: 179
Threads: 8
Joined: Sep 2023
Reputation: 0
#26
10-18-2024, 11:54 AM
(10-18-2024, 11:28 AM)Tim Curtis Wrote: Try this updated file that includes the "wait for MPD to start accepting connections after restart" code.

Code:
# Save original
sudo cp /var/www/daemon/mpdmon.php ./

# Install updated file
sudo wget -q https://raw.githubusercontent.com/moode-player/moode/1ec7f941f4966556715874a84f06222e49a65e4b/www/daemon/mpdmon.php -O /var/www/daemon/mpdmon.php
Tx. Just applied the test patch. Let you know.
Find
kurt1970 Offline
Member
*
Posts: 179
Threads: 8
Joined: Sep 2023
Reputation: 0
#27
10-18-2024, 12:06 PM
Hi @Tim Curtis 

After applying and rebooting, I now have following behavior: there occurs a buffer underrun, music stops playing, and no restarts. Also, at a first sight, nothing spectacular in the logs...

moodeutl
Code:
20241018 135417 worker: --
20241018 135417 worker: -- Startup complete
20241018 135417 worker: --
20241018 135417 worker: Mount monitor:    started
20241018 135418 worker: Radio monitor:    started
20241018 135418 worker: Watchdog monitor: started
20241018 135418 worker: Responsiveness:   Boosted
20241018 135418 worker: Ready
20241018 140005 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241018 140008 mpdmon: Buffer underrun 2 detected: Super Stereo 7
20241018 140014 mpdmon: Buffer underrun 3 detected: Super Stereo 7

Journal

Code:
moode@moode:~ $ journalctl --no-pager -S 13:58
Oct 18 14:00:08 moode systemd[1]: Starting sysstat-collect.service - system activity accounting tool...
Oct 18 14:00:08 moode systemd[1]: sysstat-collect.service: Deactivated successfully.
Oct 18 14:00:08 moode systemd[1]: Finished sysstat-collect.service - system activity accounting tool.
Oct 18 14:00:14 moode systemd[1]: Stopping mpd.service - Music Player Daemon...
Oct 18 14:00:14 moode systemd[1]: mpd.service: Deactivated successfully.
Oct 18 14:00:14 moode systemd[1]: Stopped mpd.service - Music Player Daemon.
Oct 18 14:00:14 moode systemd[1]: mpd.service: Consumed 5.656s CPU time.
Oct 18 14:00:14 moode systemd[1]: Starting mpd.service - Music Player Daemon...
Oct 18 14:00:14 moode dbus-daemon[475]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.103' (uid=0 pid=3163 comm="timedatectl")
Oct 18 14:00:14 moode systemd[1]: Starting systemd-timedated.service - Time & Date Service...
Oct 18 14:00:14 moode dbus-daemon[475]: [system] Successfully activated service 'org.freedesktop.timedate1'
Oct 18 14:00:14 moode systemd[1]: Started systemd-timedated.service - Time & Date Service.
Oct 18 14:00:14 moode mpd[3158]: Ignoring the 'pid_file' setting in systemd mode
Oct 18 14:00:14 moode systemd[1]: Started mpd.service - Music Player Daemon.
Oct 18 14:00:45 moode systemd[1]: systemd-timedated.service: Deactivated successfully.
Oct 18 14:01:45 moode dbus-daemon[475]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.111' (uid=0 pid=3385 comm="timedatectl")
Oct 18 14:01:45 moode systemd[1]: Starting systemd-timedated.service - Time & Date Service...
Oct 18 14:01:45 moode dbus-daemon[475]: [system] Successfully activated service 'org.freedesktop.timedate1'
Oct 18 14:01:45 moode systemd[1]: Started systemd-timedated.service - Time & Date Service.
Oct 18 14:02:15 moode systemd[1]: systemd-timedated.service: Deactivated successfully.
Oct 18 14:05:01 moode CRON[3749]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Oct 18 14:05:01 moode CRON[3750]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Oct 18 14:05:01 moode CRON[3749]: pam_unix(cron:session): session closed for user root
moode@moode:~ $
Find
Tim Curtis Offline
moOde audio founder
******
Posts: 13,429
Threads: 304
Joined: Mar 2018
Reputation: 545
#28
10-18-2024, 12:24 PM (This post was last modified: 10-18-2024, 12:43 PM by Tim Curtis.)
(10-18-2024, 12:06 PM)kurt1970 Wrote: Hi @Tim Curtis 

After applying and rebooting, I now have following behavior: there occurs a buffer underrun, music stops playing, and no restarts. Also, at a first sight, nothing spectacular in the logs...

moodeutl
Code:
20241018 135417 worker: --
20241018 135417 worker: -- Startup complete
20241018 135417 worker: --
20241018 135417 worker: Mount monitor:    started
20241018 135418 worker: Radio monitor:    started
20241018 135418 worker: Watchdog monitor: started
20241018 135418 worker: Responsiveness:   Boosted
20241018 135418 worker: Ready
20241018 140005 mpdmon: Buffer underrun 1 detected: Super Stereo 7
20241018 140008 mpdmon: Buffer underrun 2 detected: Super Stereo 7
20241018 140014 mpdmon: Buffer underrun 3 detected: Super Stereo 7

Journal

Code:
moode@moode:~ $ journalctl --no-pager -S 13:58
Oct 18 14:00:08 moode systemd[1]: Starting sysstat-collect.service - system activity accounting tool...
Oct 18 14:00:08 moode systemd[1]: sysstat-collect.service: Deactivated successfully.
Oct 18 14:00:08 moode systemd[1]: Finished sysstat-collect.service - system activity accounting tool.
Oct 18 14:00:14 moode systemd[1]: Stopping mpd.service - Music Player Daemon...
Oct 18 14:00:14 moode systemd[1]: mpd.service: Deactivated successfully.
Oct 18 14:00:14 moode systemd[1]: Stopped mpd.service - Music Player Daemon.
Oct 18 14:00:14 moode systemd[1]: mpd.service: Consumed 5.656s CPU time.
Oct 18 14:00:14 moode systemd[1]: Starting mpd.service - Music Player Daemon...
Oct 18 14:00:14 moode dbus-daemon[475]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.103' (uid=0 pid=3163 comm="timedatectl")
Oct 18 14:00:14 moode systemd[1]: Starting systemd-timedated.service - Time & Date Service...
Oct 18 14:00:14 moode dbus-daemon[475]: [system] Successfully activated service 'org.freedesktop.timedate1'
Oct 18 14:00:14 moode systemd[1]: Started systemd-timedated.service - Time & Date Service.
Oct 18 14:00:14 moode mpd[3158]: Ignoring the 'pid_file' setting in systemd mode
Oct 18 14:00:14 moode systemd[1]: Started mpd.service - Music Player Daemon.
Oct 18 14:00:45 moode systemd[1]: systemd-timedated.service: Deactivated successfully.
Oct 18 14:01:45 moode dbus-daemon[475]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.111' (uid=0 pid=3385 comm="timedatectl")
Oct 18 14:01:45 moode systemd[1]: Starting systemd-timedated.service - Time & Date Service...
Oct 18 14:01:45 moode dbus-daemon[475]: [system] Successfully activated service 'org.freedesktop.timedate1'
Oct 18 14:01:45 moode systemd[1]: Started systemd-timedated.service - Time & Date Service.
Oct 18 14:02:15 moode systemd[1]: systemd-timedated.service: Deactivated successfully.
Oct 18 14:05:01 moode CRON[3749]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Oct 18 14:05:01 moode CRON[3750]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Oct 18 14:05:01 moode CRON[3749]: pam_unix(cron:session): session closed for user root
moode@moode:~ $

Oops mpdmon crashes because of a missing include file. I'll fix that in bit.

The SuperStereo stream also buffer xruns on my end. This suggests a broadcaster issue.
Enjoy the Music!
moodeaudio.org | Mastodon Feed | GitHub
Website Find
Tim Curtis Offline
moOde audio founder
******
Posts: 13,429
Threads: 304
Joined: Mar 2018
Reputation: 545
#29
10-18-2024, 12:53 PM
Try these fixes then reboot. Seems to work ok on my end. That particular stream often xruns at track change.

Code:
# Fix missing include
sudo wget -q https://github.com/moode-player/moode/blob/9b7701d561777a74ebdef2067daca62bd987799a/www/daemon/mpdmon.php -O /var/www/daemon/mpdmon.php

# Truncate mpd log before starting mpdmon (prevent false positives)
sudo wget -q https://raw.githubusercontent.com/moode-player/moode/40d86470334018096a2185d6d7af8812d9bd6a34/www/daemon/worker.php -O /var/www/daemon/worker.php

sudo wget -q https://raw.githubusercontent.com/moode-player/moode/40d86470334018096a2185d6d7af8812d9bd6a34/www/command/radio.php -O /var/www/command/radio.php
Enjoy the Music!
moodeaudio.org | Mastodon Feed | GitHub
Website Find
kurt1970 Offline
Member
*
Posts: 179
Threads: 8
Joined: Sep 2023
Reputation: 0
#30
10-18-2024, 01:03 PM
testing... Keep you posted
Find
Thread Closed 


Forum Jump: