[PROBLEM] [PROBLEM] 9.x: MPD crashing ad-hoc / stops playing

[kurt1970]

Btw, glad to hear the Stream Monitor is working out for your usage scenario :-)

Welll, I used to have Naim, and they couldn't/can't/want to deal with it. So, the music stops. moOde at least retries, and mostly succeeds, which is indeed great! Thanks for that!

[kurt1970]

You must have the stream monitor enabled for that station.

It looks like watchdog and mpdmon are conflicting with one another. Basically mpdmon which runs every 6 seconds by default sees a threshold number of buffer underruns and restarts MPD. Watchdog which runs every 6 seconds happens to wake up and see that MPD is not running as would be the case during the first part of being restarted.

I'll add to the TODO list to investigate how to keep this from happening.

Thank you!

[the_bertrum]

I make extensive use of the stream monitor on my Pi3a that sits inside an old radio and plays streams all day, I've never had this restart problem. However, I've also not noticed the monitor do it's thing for a few months either....

Maybe my network has become less wobbly.

[kurt1970]

Today it's playing since +6h30 . A couple of restarts took place, but no crash yet. As Tim said, it probably has to do when mpd and the station monitor decide at the same moment to restart mpd.

Code:

moode@moode:~ $ moodeutl -l
20241011 183000 worker: --
20241011 183001 worker: -- Start moOde 9 series
20241011 183001 worker: --
20241011 183001 worker: Successfully daemonized
20241011 183001 worker: Wait for Linux startup
20241011 183007 worker: Linux startup complete
20241011 183007 worker: Boot config is ok
20241011 183007 worker: Session loaded
20241011 183008 worker: Package locks applied
20241011 183008 worker: File check complete
20241011 183008 worker: Log to RAM    on
20241011 183008 worker: Debug logging off
20241011 183008 worker: --
20241011 183008 worker: -- System
20241011 183008 worker: --
20241011 183009 worker: Host name:     moode
20241011 183009 worker: RPi model:     Pi-4B 1.2 4GB
20241011 183009 worker: moOde release: 9.1.2 2024-09-28
20241011 183009 worker: RaspiOS:       12.7 Bookworm 64-bit
20241011 183009 worker: Linux Kernel:  38 64-bit
20241011 183009 worker: MPD version:   0.23.14
20241011 183009 worker: User id:       moode
20241011 183009 worker: Home folder:   /home/moode
20241011 183009 worker: Time zone:     Europe/Brussels
20241011 183009 worker: Kbd layout:    us
20241011 183009 worker: HDMI ports(s): on
20241011 183009 worker: HDMI-CEC:      off
20241011 183009 worker: Sys LED0:      off
20241011 183009 worker: Sys LED1:      on
20241011 183009 worker: Reduce power:  n/a
20241011 183009 worker: CPU governor:  ondemand
20241011 183009 worker: Integ audio:   vc4-kms-v3d
20241011 183009 worker: --
20241011 183009 worker: -- Network
20241011 183009 worker: --
20241011 183009 worker: Eth0
20241011 183009 worker: Ethernet: adapter exists
20241011 183009 worker: Ethernet: timeout off
20241011 183009 worker: Ethernet: method  dhcp
20241011 183009 worker: Ethernet: address 192.168.1.202
20241011 183009 worker: Ethernet: netmask 255.255.255.0
20241011 183009 worker: Ethernet: gateway 192.168.1.1
20241011 183009 worker: Ethernet: pri DNS 192.168.1.1
20241011 183009 worker: Ethernet: domain  sitecom.router
20241011 183009 worker: Wlan0
20241011 183009 worker: Wireless: adapter does not exist
20241011 183009 worker: --
20241011 183009 worker: -- File sharing
20241011 183009 worker: --
20241011 183009 worker: SMB file sharing:  off
20241011 183009 worker: NFS file sharing:  off
20241011 183009 worker: DLNA file sharing: off
20241011 183009 worker: --
20241011 183009 worker: -- Special configs
20241011 183009 worker: --
20241011 183009 worker: Plexamp:          not installed
20241011 183009 worker: RoonBridge:       not installed
20241011 183009 worker: Allo Piano 2.1:   not detected
20241011 183009 worker: Allo Boss 2:      not detected, OLED script ok
20241011 183009 worker: IQaudIO AMP*:     not detected
20241011 183009 worker: --
20241011 183009 worker: -- ALSA debug
20241011 183009 worker: --
20241011 183009 worker: Cards:  0:vc4hdmi0        1:vc4hdmi1        2:G20             3:empty
20241011 183009 worker:         4:empty           5:empty           6:empty           7:empty
20241011 183010 worker: Mixers: 0:none            1:none            2:(Gato Audio Audio 2.0 Output)3:none
20241011 183010 worker:         4:none            5:none            6:none            7:none
20241011 183010 worker: --
20241011 183010 worker: -- Audio configuration
20241011 183010 worker: --
20241011 183010 worker: Audio device:  0:Gato Audio DIA-250 USB 2.0
20241011 183010 worker: ALSA card:     has been reassigned to 2 from 0
20241011 183011 worker: MPD config:    updated
20241011 183011 worker: ALSA output:   USB
20241011 183011 worker: ALSA mode:     Direct (hw)
20241011 183011 worker: ALSA mixer     Gato Audio Audio 2.0 Output
20241011 183011 worker: ALSA volume:   100% (0.00dB)
20241011 183011 worker: ALSA maxvol:   100%
20241011 183011 worker: ALSA loopback: off
20241011 183011 worker: MPD mixer      Fixed (0dB)
20241011 183011 worker: Audio formats: S32_LE
20241011 183011 worker: CamillaDSP:    off
20241011 183011 worker: CDSP volume:   0dB
20241011 183011 worker: CDSP volrange: 60dB
20241011 183011 worker: --
20241011 183011 worker: -- MPD startup
20241011 183011 worker: --
20241011 183011 worker: MPD service:        started
20241011 183011 worker: MPD port 6600:      accepting connections
20241011 183011 worker: MPD ALSA Default:   on
20241011 183011 worker: MPD ALSA Bluetooth: off
20241011 183011 worker: MPD HTTP Server:    off
20241011 183011 worker: MPD volume:         0
20241011 183011 worker: Saved MPD vol:      -1
20241011 183011 worker: Saved SRC vol:      0
20241011 183011 worker: MPD crossfade:      off
20241011 183011 worker: MPD ignore CUE:     yes
20241011 183011 worker: MPD CDSP volsync:   off
20241011 183011 worker: --
20241011 183011 worker: -- Music sources
20241011 183011 worker: --
20241011 183011 worker: USB drives:     none
20241011 183011 worker: NVMe drives:    none
20241011 183011 worker: NAS source:     Music (cifs)
20241011 183020 worker: --
20241011 183020 worker: -- Feature availability
20241011 183020 worker: --
20241011 183020 worker: Input select:    available, Source: MPD, Output: Gato Audio DIA-250 USB 2.0
20241011 183020 worker: Bluetooth:       available, PIN: None, ALSA/CDSP maxvol: 100%/0dB, ALSA outmode: Standard
20241011 183020 worker: AirPlay:         available
20241011 183020 worker: Spotify Connect: available
20241011 183020 worker: Squeezelite:     available
20241011 183020 worker: UPnP client:     available
20241011 183020 worker: Plexamp:         not installed, ALSA maxvol: 100%
20241011 183020 worker: RoonBridge:      not installed
20241011 183020 worker: Multiroom:       available
20241011 183020 worker: GPIO buttons:    available
20241011 183020 worker: Stream recorder: n/a
20241011 183020 worker: --
20241011 183020 worker: -- Security
20241011 183020 worker: --
20241011 183020 worker: Web SSH server:    off
20241011 183020 worker: XSS detection:     off
20241011 183020 worker: HTTPS mode:        available
20241011 183020 worker: --
20241011 183020 worker: -- Peripherals
20241011 183020 worker: --
20241011 183022 worker: Local display:   off
20241011 183022 worker: HDMI 4K 60Hz:    off
20241011 183022 worker: On-screen kbd:   off
20241011 183022 worker: Rotary encoder:  off
20241011 183022 worker: USB volume knob: off
20241011 183022 worker: LCD updater:     off
20241011 183022 worker: --
20241011 183022 worker: -- Miscellaneous
20241011 183022 worker: --
20241011 183022 worker: Software update:   Automatic check on
20241011 183022 worker: Software update:   Checking for available update...
20241011 183022 worker: Software update:   Software is up to date
20241011 183022 worker: Auto-CoverView:    off
20241011 183022 worker: CoverView timeout: Never
20241011 183022 worker: Auto-shuffle:      off
20241011 183022 worker: Auto-play:         on, via playid 44
20241011 183022 worker: Maintenance task:  360 mins
20241011 183022 worker: Current view:      reset to Playback
20241011 183022 worker: Active flags:      all false
20241011 183022 worker: Reset flags:       skipped
20241011 183023 worker: Session check:     ok
20241011 183023 worker: --
20241011 183023 worker: -- Startup complete
20241011 183023 worker: --
20241011 183023 worker: Mount monitor:    started
20241011 183023 worker: Radio monitor:    started
20241011 183023 worker: Watchdog monitor: started
20241011 183023 worker: Responsiveness:   Boosted
20241011 183023 worker: Ready
20241011 183023 mpdmon: Buffer underrun 1 detected: Pure Lounge Radio
20241011 183023 mpdmon: Buffer underrun 2 detected: Pure Lounge Radio
20241011 183023 mpdmon: Buffer underrun 3 detected: Pure Lounge Radio
20241011 183023 mpdmon: MPD restarted, play resumed
20241011 183023 mpdmon: Buffer underrun 1 detected: Pure Lounge Radio
20241011 183023 mpdmon: Buffer underrun 2 detected: Pure Lounge Radio
20241011 183023 mpdmon: Buffer underrun 3 detected: Pure Lounge Radio
20241011 183024 mpdmon: MPD restarted, play resumed
20241011 183024 mpdmon: Buffer underrun 1 detected: Pure Lounge Radio
20241011 183024 mpdmon: Buffer underrun 2 detected: Pure Lounge Radio
20241011 183024 mpdmon: Buffer underrun 3 detected: Pure Lounge Radio
20241012 081535 mpdmon: MPD restarted, play resumed
20241012 085406 mpdmon: Buffer underrun 1 detected: VRT Radio 2 West-Vlaanderen
20241012 085409 mpdmon: Buffer underrun 2 detected: VRT Radio 2 West-Vlaanderen
20241012 085415 mpdmon: Buffer underrun 3 detected: VRT Radio 2 West-Vlaanderen
20241012 085415 mpdmon: MPD restarted, play resumed
20241012 095303 worker: Job update_library
20241012 095303 mpdindex: Start
20241012 095303 mpdindex: Cmd (update)
20241012 095303 thumb-gen: Start
20241012 095303 thumb-gen: Scan opt: Default
20241012 095303 thumb-gen: Priority: Cover image file
20241012 095303 thumb-gen: Res,Qual: 600px,60
20241012 095303 thumb-gen: Px ratio: 1
20241012 095303 thumb-gen: Th width: 600
20241012 095303 thumb-gen: Thm qual: 60
20241012 095303 thumb-gen: Scanning: NAS
20241012 095349 thumb-gen: Done: 2543 folders scanned, 4 thumbs created, 2539 already in cache.
20241012 095445 mpdindex: Done: indexed 2323 artists, 2481 albums, 27903 songs
20241012 095445 worker: Job update_library done
20241012 102440 mpdmon: Buffer underrun 1 detected: VRT Radio 2 West-Vlaanderen
20241012 102446 mpdmon: Buffer underrun 2 detected: VRT Radio 2 West-Vlaanderen
20241012 102449 mpdmon: Buffer underrun 3 detected: VRT Radio 2 West-Vlaanderen
20241012 102449 mpdmon: MPD restarted, play resumed
20241012 114607 mpdmon: Buffer underrun 1 detected: Pure Lounge Radio
20241012 114613 mpdmon: Buffer underrun 2 detected: Pure Lounge Radio
20241012 114616 mpdmon: Buffer underrun 3 detected: Pure Lounge Radio
20241012 114617 mpdmon: MPD restarted, play resumed
20241012 134651 mpdmon: Buffer underrun 1 detected: Pure Lounge Radio
20241012 134654 mpdmon: Buffer underrun 2 detected: Pure Lounge Radio
20241012 134700 mpdmon: Buffer underrun 3 detected: Pure Lounge Radio
20241012 134700 mpdmon: MPD restarted, play resumed
20241012 143453 mpdmon: Buffer underrun 1 detected: Pure Lounge Radio

[TheOldPresbyope]

Since i haven’t experienced them, I don’t know what the audio effect is of these underrun/restart events. Is is just an audio dropout?

To follow up on Tim’s remark, Comcast is our ISP and Ashburn Virginia is just 30 miles away as the crow flies. For those who don’t know it, some two-thirds of the world’s Internet traffic passes through the interchanges in Ashburn. New data centers keep cropping up like mushrooms in this region along with the power lines and optical fibers to feed them. The Internet service keeps getting faster but there’s a growing concern over quality-of-life issues for area residents. It’s not the pastoral countryside it used to be.

Regards,
Kent

[kurt1970]

With the monitor on, the effect is that the audio drops when a buffer underrun occurs, and comes back a few seconds later. If the monitor is not active and an underrun occurs, music does not come back. Works quite good in most cases.

[the_bertrum]

Kent, the buffer under-run results in the no sound, but all other signs are that the stream is still playing. A stop/start of the stream will bring it back, but the monitor will just restart MPD entirely. With the monitor you lose maybe a second or so of the stream, without the monitor, you need a manual intervention to bring it back.

I used to see these on some stations several times a day, but lately I can't remember that last time it happened. When I was testing the monitor it took several days before I saw it kick in once.

I suspect the culprit is at the source of the station, or in the LAN, or most likely a combination of both. I posit this hypothesis because it does not affect all stations (so the source is a significant variable), but it also does not affect all listeners stations it does affect (so the local user setup is a significant variable also).

[kurt1970]

You must have the stream monitor enabled for that station.

It looks like watchdog and mpdmon are conflicting with one another. Basically mpdmon which runs every 6 seconds by default sees a threshold number of buffer underruns and restarts MPD. Watchdog which runs every 6 seconds happens to wake up and see that MPD is not running as would be the case during the first part of being restarted.

I'll add to the TODO list to investigate how to keep this from happening.

Hi @Tim Curtis Is this something considered for the 9.1.3 release?

Fact is the more situations of a buffer underrun occur, the more chance of having the conflcting situation of moOde restarting MDP, while MPD is restarting already. As you can see, this happens quite frequently (a couple of times in seconds). After the crash, MPD doesn't recover and music is stopped.

moodeutl log

Code:

20241016 084430 watchdog: MPD crashed and was restarted (check journal for messages)
20241016 084431 mpdmon: Buffer underrun 3 detected: Super Stereo 7 (CD Q)
20241016 084431 mpdmon: MPD restarted, play resumed
20241016 084431 mpdmon: Buffer underrun 1 detected: Super Stereo 7 (CD Q)
20241016 084431 mpdmon: Buffer underrun 2 detected: Super Stereo 7 (CD Q)
20241016 084431 mpdmon: Buffer underrun 3 detected: Super Stereo 7 (CD Q)
20241016 084431 mpdmon: MPD restarted, play resumed
20241016 084431 mpdmon: Buffer underrun 1 detected: Super Stereo 7 (CD Q)
20241016 084431 mpdmon: Buffer underrun 2 detected: Super Stereo 7 (CD Q)
20241016 084431 mpdmon: Buffer underrun 3 detected: Super Stereo 7 (CD Q)
20241016 084431 mpdmon: MPD restarted, play resumed
20241016 084431 mpdmon: Buffer underrun 1 detected: Super Stereo 7 (CD Q)
20241016 084431 mpdmon: Buffer underrun 2 detected: Super Stereo 7 (CD Q)
20241016 084431 mpdmon: Buffer underrun 3 detected: Super Stereo 7 (CD Q)
20241016 084431 mpdmon: MPD restarted, play resumed
20241016 084431 mpdmon: Buffer underrun 1 detected: Super Stereo 7 (CD Q)
20241016 084431 mpdmon: Buffer underrun 2 detected: Super Stereo 7 (CD Q)
20241016 084431 mpdmon: Buffer underrun 3 detected: Super Stereo 7 (CD Q)
20241016 084431 mpdmon: MPD restarted, play resumed
20241016 084431 mpdmon: Buffer underrun 1 detected: Super Stereo 7 (CD Q)
20241016 084431 mpdmon: Buffer underrun 2 detected: Super Stereo 7 (CD Q)
20241016 084431 mpdmon: Buffer underrun 3 detected: Super Stereo 7 (CD Q)
20241016 084431 mpdmon: MPD restarted, play resumed
20241016 084431 mpdmon: Buffer underrun 1 detected: Super Stereo 7 (CD Q)
20241016 084436 watchdog: MPD crashed and was restarted (check journal for messages)

Journal

Code:

Oct 16 08:44:28 moode systemd[1]: mpd.service: Deactivated successfully.
Oct 16 08:44:28 moode systemd[1]: Stopped mpd.service - Music Player Daemon.
Oct 16 08:44:28 moode systemd[1]: mpd.service: Start request repeated too quickly.
Oct 16 08:44:28 moode systemd[1]: mpd.service: Failed with result 'start-limit-hit'.
Oct 16 08:44:28 moode systemd[1]: Failed to start mpd.service - Music Player Daemon.
Oct 16 08:44:30 moode systemd[1]: mpd.service: Start request repeated too quickly.
Oct 16 08:44:30 moode systemd[1]: mpd.service: Failed with result 'start-limit-hit'.
Oct 16 08:44:30 moode systemd[1]: Failed to start mpd.service - Music Player Daemon.
Oct 16 08:44:31 moode systemd[1]: mpd.service: Start request repeated too quickly.
Oct 16 08:44:31 moode systemd[1]: mpd.service: Failed with result 'start-limit-hit'.
Oct 16 08:44:31 moode systemd[1]: Failed to start mpd.service - Music Player Daemon.
Oct 16 08:44:31 moode systemd[1]: mpd.service: Start request repeated too quickly.
Oct 16 08:44:31 moode systemd[1]: mpd.service: Failed with result 'start-limit-hit'.
Oct 16 08:44:31 moode systemd[1]: Failed to start mpd.service - Music Player Daemon.
Oct 16 08:44:31 moode systemd[1]: mpd.service: Start request repeated too quickly.
Oct 16 08:44:31 moode systemd[1]: mpd.service: Failed with result 'start-limit-hit'.
Oct 16 08:44:31 moode systemd[1]: Failed to start mpd.service - Music Player Daemon.
Oct 16 08:44:31 moode systemd[1]: mpd.service: Start request repeated too quickly.
Oct 16 08:44:31 moode systemd[1]: mpd.service: Failed with result 'start-limit-hit'.
Oct 16 08:44:31 moode systemd[1]: Failed to start mpd.service - Music Player Daemon.
Oct 16 08:44:31 moode systemd[1]: mpd.service: Start request repeated too quickly.
Oct 16 08:44:31 moode systemd[1]: mpd.service: Failed with result 'start-limit-hit'.
Oct 16 08:44:31 moode systemd[1]: Failed to start mpd.service - Music Player Daemon.
Oct 16 08:44:31 moode systemd[1]: mpd.service: Start request repeated too quickly.
Oct 16 08:44:31 moode systemd[1]: mpd.service: Failed with result 'start-limit-hit'.
Oct 16 08:44:31 moode systemd[1]: Failed to start mpd.service - Music Player Daemon.

[Tim Curtis]

Yes it's part of upcoming 9.1.3
https://github.com/moode-player/moode/co...9a77199e09

[kurt1970]

Yes it's part of upcoming 9.1.3
https://github.com/moode-player/moode/co...9a77199e09

Brilliant!