MPD not playing most (but not all) streams anymore

Need help with MPD?
Post Reply
Zefiro
Posts: 3
Joined: February 28th, 2021, 8:37 am

MPD not playing most (but not all) streams anymore

Post by Zefiro »

Hello,

I've been using MPD for several years now, as replacement for Winamp. It mostly works great and I was quite happy - until yesterday. I took a look at Mopidy for it's 'play from Youtube' functionality, and MPD seems to have gotten jealous. Thus I'm seeking your help now.

My MPD runs on a headless (no X installed) Raspi (named 'grag') and is used to play free streams from the web (no local music collection).
Since official repos tend to be outdated (though the current 0.21.5 doesn't sound so bad anymore), I'm compiling mpd myself (using this description). To take care of possible dependencies, I install mpd first via apt, then overwrite it with the one build from source. I'm aware that apt installs to /usr/bin/mpd whereas source-install places it in /usr/local/bin/mpd and solve this via replacing the former with a symlink to the latter.

This has worked fine for me, until yesterday when - in the process of trying out Mopidy - I did a system update (apt update && apt -y upgrade && apt -y autoremove). Mopidy did not satisfy me, so I stopped it, started mpd again, and...

Symptoms:
Most streams I have in my queue do not produce sound anymore. They are shown as 'playing'.
Some streams - including one from Youtube (url generated by /usr/local/bin/youtube-dl -g -f bestaudio <url>) as well as one local file - however DO work.
This rules out any general configuration, ALSA or hardware issues. (and makes it darn hard to google for it)
Initially mpd also failed to stop (systemctl stop mpd would hang for minutes, then hard-kill mpd) - this has been resolved by reinstalling it.

Expectation:
All streams (of those which used to work) should play and also produce sound. Or at least an error message should be shown.

Examples:
http://deep.friskyradio.com/friskydeep_aachi
"mpg123" says: MPEG 1.0 L III cbr96 32000 j-s
MPD: plays fine, as expected
VLC (on a windows machine): works fine

http://chill.friskyradio.com/friskychill_mp3_high
"mpg123" says: MPEG 1.0 L III cbr128 44100 j-s
MPD: "plays", no audio output
VLC (on a windows machine): works fine

https://hirschmilch.de:7001/psytrance.mp3
(can't test mpd123, as this doesn't work with secure http)
MPD: "plays", no audio output
VLC (on a windows machine): works fine (says: 44,1kHz 128kB/s stereo)

http://ca.ah.fm/192k
"mpg123" says: MPEG 1.0 L III cbr192 44100 stereo
MPD: "plays", no audio output
VLC (on a windows machine): works fine (says: VLC OK: 44,1kHz 192kB/s stereo)

Steps I've tried so far:
  • tested general audio output, works: aplay /usr/share/sounds/alsa/Front_Center.wav
  • rebooted
  • updated my mpd to newest (0.22.6)
  • 'apt remove mpd', 'apt install mpd', 'ninja -C output/release install' (and making sure the right version is started again)
  • (while mpd was stopped) deleted first /var/lib/mpd/state, then also the whole /var/lib/mpd (and recreated the directory structure)
  • created this forum post
Technical details
# cat /proc/cpuinfo | egrep "(model|Model|Hardware)" | uniq
model name : ARMv7 Processor rev 4 (v7l)
Hardware : BCM2835
Model : Raspberry Pi 3 Model B Plus Rev 1.3
# uname -a
Linux grag 5.10.11-v7+ #1399 SMP Thu Jan 28 12:06:05 GMT 2021 armv7l GNU/Linux
# apt search mpd|grep installed
libmpdclient-dev/stable,now 2.16-1 armhf [installed]
libmpdclient2/stable,now 2.16-1 armhf [installed,automatic]
libmpdec2/stable,now 2.4.2-2 armhf [installed,automatic]
mopidy/stable,now 3.1.1-1 all [installed]
mopidy-mpd/stable,now 3.1.0-1 all [installed]
mopidy-soundcloud/stable,now 3.0.1-1 all [installed]
mpd/stable,now 0.21.5-3 armhf [installed]
rtmpdump/stable,now 2.4+20151223.gitfa8646d.1-2 armhf [installed,automatic]
triggerhappy/stable,now 0.5.0-1 armhf [installed,automatic]
# systemctl status mpd
? mpd.service - Music Player Daemon
Loaded: loaded (/usr/local/lib/systemd/system/mpd.service; enabled; vendor preset: enabled)
Active: active (running) since Sun 2021-02-28 09:33:55 CET; 4min 59s ago
Docs: man:mpd(1)
man:mpd.conf(5)
Main PID: 4671 (mpd)
Tasks: 6 (limit: 2181)
CGroup: /system.slice/mpd.service
mq4671 /usr/bin/mpd --no-daemon /etc/mpd.conf
# /usr/bin/mpd --version|head -n 1
Music Player Daemon 0.22.6 (0.22.6)
# cat /etc/default/mpd | grep -v "^\\s*#" | grep -v "^\\s*$"
MPDCONF=/etc/mpd.conf
# cat /etc/mpd.conf | grep -v "^\\s*#" | grep -v "^\\s*$"
music_directory "/var/lib/mpd/music"
playlist_directory "/var/lib/mpd/playlists"
db_file "/var/lib/mpd/tag_cache"
log_file "/var/log/mpd/mpd.log"
pid_file "/run/mpd/pid"
state_file "/var/lib/mpd/state"
sticker_file "/var/lib/mpd/sticker.sql"
user "mpd"
bind_to_address "any"
follow_outside_symlinks "yes"
follow_inside_symlinks "yes"
zeroconf_enabled "yes"
zeroconf_name "Music Player @ %h"
input {
plugin "curl"
}
input {
enabled "no"
plugin "qobuz"
}
input {
enabled "no"
plugin "tidal"
}
decoder {
plugin "hybrid_dsd"
enabled "no"
}
audio_output {
type "alsa"
name "My ALSA Device"
mixer_type "software"
}
filesystem_charset "UTF-8"
# lsof -i -P -n | grep LISTEN | grep -i mpd
mpd 4671 mpd 10u IPv6 52679 0t0 TCP *:6600 (LISTEN)
# systemctl stop mpd && rm /var/log/mpd/mpd.log && systemctl start mpd && sleep 60 && cat /var/log/mpd/mpd.log
Feb 28 10:21 : avahi: Service 'Music Player @ grag' successfully established.
Noteable lines from /var/log/syslog involving mpd are only:
Feb 28 10:21:25 grag systemd[1]: mpd.service: Succeeded.
Feb 28 10:21:26 grag mpd[5378]: Feb 28 10:21 : exception: bind to '0.0.0.0:6600' failed (continuing anyway, because binding to '[::]:6600' succeeded): Failed to bind socket: Address already in use
Feb 28 10:21:26 grag mpd[5378]: Feb 28 10:21 : exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
I do not know 'wildmidi' nor do I have midi files in my queue. So I'm ignoring this.
I do not understand why it claims it can't bind to IPv4 TCP 6600, as lsof does not show this port as in use when mpd is stopped, and when it's started, only the IPv6 variant is used (my mpd). Connections to mpd do work, though, so I'm ignoring this one as well.

It is well possible that the issue is with another part of the system, probably due to the update. I'm at a loss at where to look for it, though.
Any ideas would be greatly appreciated.
max
Forum team
Posts: 1236
Joined: January 15th, 2013, 3:43 pm

Re: MPD not playing most (but not all) streams anymore

Post by max »

I can play all of those streams. Post a verbose log of MPD, playing each stream. And read https://www.musicpd.org/help/
Note that you're not using an ALSA "hw" device. Doing that would reduce CPU usage and would improve quality.
max
Forum team
Posts: 1236
Joined: January 15th, 2013, 3:43 pm

Re: MPD not playing most (but not all) streams anymore

Post by max »

And: note that Raspi kernel 5.10 is known to be buggy. I don't know if yours is already fixed, but it might worth trying an older kernel.
See https://github.com/MusicPlayerDaemon/MPD/issues/1056
Zefiro
Posts: 3
Joined: February 28th, 2021, 8:37 am

Re: MPD not playing most (but not all) streams anymore

Post by Zefiro »

Thanks for responding.

And yes, all those streams do work for me as well when using other players.

I had hoped to add enough information, but that --verbose has slipped by. Here's a log of it when using it to play four streams sequentially. The first one (Frisky Deep) does work (produce sound), the other three are silent. They look similar to me on the log output.

(Note I've removed a lot of repetitive "Client" status requests & responses which seemed unrelated to playing)
# /usr/bin/mpd --stderr --no-daemon --verbose /etc/mpd.conf 2>&1 | tee mpdlog.txt
config_file: loading file /etc/mpd.conf
exception: bind to '0.0.0.0:6600' failed (continuing anyway, because binding to '[::]:6600' succeeded): Failed to bind socket: Address already in use
path: SetFSCharset: fs charset is:
libsamplerate: libsamplerate converter 'Fastest Sinc Interpolator'
vorbis: Xiph.Org libVorbis 1.3.6
opus: libopus 1.3
sndfile: libsndfile-1.0.28
exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
adplug: adplug 2.2.1
simple_db: reading DB
curl: version 7.64.0
curl: with GnuTLS/3.6.7
avahi: Initializing interface
exception: RTIOThread could not get realtime scheduling, continuing anyway: sched_setscheduler failed: Operation not permitted
avahi: Client changed to state 2
avahi: Client is RUNNING
avahi: Registering service _mpd._tcp/Music Player @ grag
avahi: Service group changed to state 0
avahi: Service group is UNCOMMITED
state_file: Loading state file /var/lib/mpd/state
avahi: Service group changed to state 1
avahi: Service group is REGISTERING
client: [0] opened from 10.20.30.204:42252
avahi: Service group changed to state 2
avahi: Service 'Music Player @ grag' successfully established.
client: [1] process command "addid "http://deep.friskyradio.com/friskydeep_aachi" 0"
client: [1] command returned 0
client: [1] process command "play"
playlist: play 0:"http://deep.friskyradio.com/friskydeep_aachi"
client: [1] command returned 0
client: [0] process command "plchanges "2""
client: [0] command returned 0
curl: icy-metaint=8192
decoder_thread: probing plugin mad
decoder: audio_format=32000:24:2, seekable=false
exception: OutputThread could not get realtime scheduling, continuing anyway: sched_setscheduler failed: Operation not permitted
client: [0] process command "status"
alsa_output: opened default type=PLUG
alsa_output: buffer: size=320..32768 time=10000..1024000
alsa_output: period: size=320..32768 time=10000..1024000
alsa_output: default period_time = buffer_time/4 = 500000/4 = 125000
alsa_output: format=S24_LE (Signed 24 bit Little Endian)
alsa_output: buffer_size=16000 period_size=4000
output: opened "My ALSA Device" (alsa) audio_format=32000:24:2
client: [0] command returned 0
client: [0] process command "plchanges "4""
client: [0] command returned 0
client: [1] process command "clear"
playlist: stop
player: played "http://deep.friskyradio.com/friskydeep_aachi"
output: closed "My ALSA Device" (alsa)
client: [1] command returned 0
client: [1] process command "addid "http://chill.friskyradio.com/friskychill_mp3_high" 0"
client: [1] command returned 0
client: [1] process command "play"
playlist: play 0:"http://chill.friskyradio.com/friskychill_mp3_high"
client: [1] command returned 0
client: [0] process command "plchanges "5""
client: [0] command returned 0
curl: icy-metaint=8192
decoder_thread: probing plugin mad
decoder: audio_format=44100:24:2, seekable=false
client: [0] process command "status"
alsa_output: opened default type=PLUG
alsa_output: buffer: size=444..32768 time=10068..743039
alsa_output: period: size=444..32768 time=10068..743039
alsa_output: default period_time = buffer_time/4 = 500000/4 = 125000
alsa_output: format=S24_LE (Signed 24 bit Little Endian)
alsa_output: buffer_size=22050 period_size=5512
output: opened "My ALSA Device" (alsa) audio_format=44100:24:2
client: [0] command returned 0
client: [0] process command "plchanges "7""
client: [0] command returned 0
client: [1] process command "clear"
playlist: stop
player: played "http://chill.friskyradio.com/friskychill_mp3_high"
output: closed "My ALSA Device" (alsa)
client: [1] command returned 0
client: [1] process command "addid "http://ca.ah.fm/192k" 0"
client: [1] command returned 0
client: [1] process command "play"
playlist: play 0:"http://ca.ah.fm/192k"
client: [1] command returned 0
client: [0] process command "plchanges "9""
client: [0] command returned 0
curl: icy-metaint=16384
decoder_thread: probing plugin mad
decoder: audio_format=44100:24:2, seekable=false
alsa_output: opened default type=PLUG
client: [0] process command "status"
alsa_output: buffer: size=444..32768 time=10068..743039
alsa_output: period: size=444..32768 time=10068..743039
alsa_output: default period_time = buffer_time/4 = 500000/4 = 125000
alsa_output: format=S24_LE (Signed 24 bit Little Endian)
alsa_output: buffer_size=22050 period_size=5512
output: opened "My ALSA Device" (alsa) audio_format=44100:24:2
client: [0] command returned 0
client: [0] process command "plchanges "11""
client: [0] command returned 0
client: [1] process command "clear"
playlist: stop
player: played "http://ca.ah.fm/192k"
output: closed "My ALSA Device" (alsa)
client: [1] command returned 0
client: [1] process command "addid "http://relay4.slayradio.org:8000/" 0"
client: [1] command returned 0
client: [1] process command "play"
playlist: play 0:"http://relay4.slayradio.org:8000/"
client: [1] command returned 0
client: [0] process command "plchanges "13""
client: [0] command returned 0
curl: icy-metaint=8192
decoder_thread: probing plugin mad
decoder: audio_format=44100:24:2, seekable=false
client: [0] process command "status"
alsa_output: opened default type=PLUG
alsa_output: buffer: size=444..32768 time=10068..743039
alsa_output: period: size=444..32768 time=10068..743039
alsa_output: default period_time = buffer_time/4 = 500000/4 = 125000
alsa_output: format=S24_LE (Signed 24 bit Little Endian)
alsa_output: buffer_size=22050 period_size=5512
output: opened "My ALSA Device" (alsa) audio_format=44100:24:2
client: [0] command returned 0
client: [0] process command "plchanges "15""
client: [0] command returned 0
My mpd config is basically the installation default with the exception of using "mixer_type software". Is this what you were referring to? If I remember correctly, that was chosen as otherwise using the volume sliders in the mpd client wouldn't work.

I looked into the Github issue you mentioned, though I'm lacking the Alsa experience to understand it. From what I get is that he has different output devices and some work, while the "copy" type does not. All I can say is that "grep -ir copy /etc/alsa/*" does not return anything. Also my issue is reproducible based in input streams - the "Frisky Deep" always work, the others currently always fail.
If you still expect this might be a kernel issue I'll look into how I can downgrade it.

So I'd suspect an issue with some of those streams (type of encoding?) and mpd (or parts of it's decoding logic), though here I'm stuck. Is mpd using external libraries or programs to decode those streams?
max
Forum team
Posts: 1236
Joined: January 15th, 2013, 3:43 pm

Re: MPD not playing most (but not all) streams anymore

Post by max »

Everything looks fine in your log. If I understood you correctly, then only the first stream is audible. The one thing that is different in the first stream is that its sample rate is 32 kHz, the others have 44.1 kHz. 32 kHz is unusual, and it's unusual that a "standard" sample rate like 44.1 kHz fails. No idea why.

I believe the problem is in the output, not in the decoder. Try adding
device "hw:0"
.. to your audio_output section (or "hw:1" if that didn't work). That circumvents all ALSA plugins.
Zefiro
Posts: 3
Joined: February 28th, 2021, 8:37 am

Re: MPD not playing most (but not all) streams anymore

Post by Zefiro »

That did the trick!
Everything seems to be working fine now again (at least those handful of streams I usually listen to)

Many thanks!

I've never changed anything in the audio setup except the Alsa output device, so possibly the update introduced something here.
I realize this is outside of the mpd scope, but might you know how I could look into what could cause this in the Alsa chain?
Or how I could provoce this outside of mpd? As "mpg123 -v http://relay4.slayradio.org:8000/" tells me it's using Alsa as well ("Decoder: generic / Trying output module: alsa, device: <nil>"
Just in case I'd need to actually use Alsa in the future - or possibly someone else coming here from Google.
max
Forum team
Posts: 1236
Joined: January 15th, 2013, 3:43 pm

Re: MPD not playing most (but not all) streams anymore

Post by max »

No, I have no idea what may cause this. I never use any ALSA plugins, I always use "hw" devices directly. As I already mentioned here, this reduces CPU usage and increases quality - it's a win-win.
Post Reply