Better communicate streaming problems

[iafan]

I've been debugging some MPD playback issues on Orange Pi/Armbian for quite some time now, and while after many experiments I think these are caused not by MPD, but by a buggy Wi-Fi stack, I wish MPD had some better problem reporting in the first place. Currently the bug manifests itself in MPD starting to pause the playback for half a second each second (I can share an audio clip of such buggy playback, if needed), and this can continue for several minutes, but even with verbose logging there's nothing in the log except periodic 'state_file: Saving state file /var/lib/mpd/state' messages.

What I wish to have had in the verbose logs is:

• Events when the buffer is underrun or is below some threshold
• Periodic information on how full the audio buffer is

It also makes sense to report these as events to which clients could subscribe and act accordingly.

[MaxKellermann]

There are already log messages in the ALSA output for buffer xruns.

[iafan]

Yeah, but I believe these are different (and please correct me here if I'm wrong): ALSA ring buffer is a low-level one, and its issues can come from various potential causes:

1. ALSA bugs themselves
2. MPD not being able to provide data in time while it has data in its own buffer (due to some bug)
3. MPD not being able to provide data in time because its own buffer (controlled by audio_buffer_size) has depleted (legitimate scenario in case of networking issues).

What I'm trying to debug doesn't look like ALSA buffer issues, but more of issues with MPD's own audio buffer (again, I'm not saying this is an MPD bug, but MPD, through some better logging, could help track these issues down).

A little more background on the issue: once in a while (it can be 30 minutes, or it can be 6+ hours of continuous online radio streaming, the sudden gaps in the playback start to appear (demo mp3). This can last for a few minutes and then cure by itself. Sometimes it causes MPD to stop completely. During this broken playback, MPD doesn't report any problems in the log. Restarting MPD service during such playback often — but not always — helps. Reloading the WiFi kernel driver often — but again, not always — helps. Both reloading the kernel driver and restarting MPD after that is guaranteed to help. So I'm not really sure what is going on there, and thus was reluctant to file a bug against MPD, but I'm pretty positive that MPD could at least report its own buffer statistics to help track down issues like this. Would also love to hear your input on what you think this playback issue is about and how to debug it better.

[MaxKellermann]

The MPD core has no such thing as "not able to provide data in time", because it does not track time. It does not know or care what time it is; it only routes audio chunks coming from the decoder to the output, as quickly as the chunks are being decoded, and as quickly as the output is capable of consuming them. So MPD's internal buffer is not the right place to measure anything. Logging its level periodically also won't help with your problem, because this may either spam the log very quickly, or is too slow and you may miss the time when it really drains empty.

But one consequence of MPD's buffer draining empty is that the ALSA buffer will also drain empty very very quickly (usually within hundreds of milliseconds), and that event will be logged.

If you don't see that in the (verbose) log, then what you observe is not a problem with an empty buffer! It may be a decoder failure due to corrupt data on the stream, or something else, but not a buffering problem.

[iafan]

Thanks for the detailed explanation, Max. By "not able to provide data in time" I meant that — from the point of view of an external observer — MPD is not pumping enough data for an uninterrupted playback.

MPD not only pumps the data from the decoder into ALSA, but also from the network (curl) into the decoder, right? This is basically what I'm most interested peeking at. Basically, at any given point in time I'd want to have the following question answered: "Is my network good enough to stream the audio I'm currently playing". One might argue if this information is useful, since I'm probably trying to solve some edge case, but I believe it would be generally useful for the clients to be able to indicate that somehow in the UI, or to switch to a lower bitrate stream if that is available.

Now, back to my edge case with the bug that I experience. After some more investigation and experiments, here's what I think is happening: from time to time, while continuously streaming radio, my network becomes 'slow' from the perspective of the OPi board: the ping time increases, and it can last from a few seconds to a few minutes before things will get back to normal. This could be a problem with the OPi board itself, it's WiFi driver, my router, or an unlucky combination of these factors). Under these circumstances, MPD starts depleting its own buffer(s), and in the end the audio becomes choppy as in the sample recording I provided above. Even once the network stabilizes, MPD can't easily recover by itself, still producing choppy audio until I restart the mpd service. This immediately fixes the issues.

So I tend to think there is some bug in the chain (curl-mpd-decoder-mpd-alsa), which I don't really know how to isolate. If I run a side watchdog script that constantly pings some remote server and, once it sees increase in the ping time, restarts the WiFi driver which causes a reconnect, I nip the network problem in the bud, and MPD continues it playback just fine because it still has some data in its buffer while WiFi connection is reestablished (which takes 4-5 seconds).

This issue occurs on MPD 0.19.12 (jessie-backports), 0.19.21 (stretch) and 0.20.4 (experimental). I'd love to help with isolating it (for which more verbose logging might be handy).

TL;DR: I think there's some issue with MPD recovering from network outages/slowness, and while I've found some workaround to prevent network outages from happening, I think there's some room for improvement on MPD side as well.

[joerg-krause]

curl has some options like CURLOPT_LOW_SPEED_LIMIT and CURLOPT_LOW_SPEED_TIME which can be used to detect poor network connections. I use these options in the curl input plugin so MPD stops streaming in case of a dropped network connection.

[iafan]

@joerg-krause I think the definition of a 'poor connection' is relative to the stream bitrate. What is good for 32kbps will not be enough for 320kbps, and since we don't know the stream bitrate beforehand, there's no way to have a one-size-fits-all value for these settings.

But your comment actually led me to thinking if there's any way to tell curl to provide some statistics while it is being used by MPD. I see curl has CURLOPT_VERBOSE and CURLOPT_STDERR settings that allow one to redirect logging to some file, but I'm not sure if there's any way to control that from within MPD config itself. I think having such logging would be useful.

[moodeaudio]

@joerg-krause,

What method are u using to set curl options for MPD?

I tried placing them in ~/.curlrc and not having success from within MPD but from cmd line it work ok curl 7.38.0

pi@rp3:~ $ cat ~/.curlrc --speed-limit 32000 --speed-time 3 --connect-timeout 5

Tested first url from radio station list below and success using curl from cmd line. pi@rp3:~ $ curl http://173.244.199.248:80 curl: (28) Connection timed out after 5000 milliseconds

Tested using MPD (0.20.6) a set of radio stations with non working links. Connection timeouts are 10 secs instead of 5

mpd.log . . . Apr 30 08:12 : exception: Failed to decode http://173.244.199.248:80 Apr 30 08:12 : exception: nested: CURL failed: Connection timed out after 10008 milliseconds Apr 30 08:12 : player: played "http://173.244.199.248:80" Apr 30 08:12 : exception: Failed to decode http://72.55.137.198:3200 Apr 30 08:12 : exception: nested: CURL failed: Connection timed out after 10008 milliseconds Apr 30 08:12 : player: played "http://72.55.137.198:3200" Apr 30 08:13 : exception: Failed to decode http://141.217.119.14:8000/AnnChannel Apr 30 08:13 : exception: nested: CURL failed: Connection timed out after 10006 milliseconds Apr 30 08:13 : player: played "http://141.217.119.14:8000/AnnChannel" Apr 30 08:13 : exception: Failed to decode http://shoutmedia.abc.net.au:10464 Apr 30 08:13 : exception: nested: CURL failed: Connection timed out after 10008 milliseconds Apr 30 08:13 : player: played "http://shoutmedia.abc.net.au:10464" Apr 30 08:13 : exception: Failed to decode http://shoutmedia.abc.net.au:10426 Apr 30 08:13 : exception: nested: CURL failed: Connection timed out after 10008 milliseconds Apr 30 08:13 : player: played "http://shoutmedia.abc.net.au:10426" Apr 30 08:13 : exception: Failed to decode http://ucfm.com.au:8000/listen.mp3 Apr 30 08:13 : exception: nested: CURL failed: Connection timed out after 10007 milliseconds Apr 30 08:13 : player: played "http://ucfm.com.au:8000/listen.mp3"

[joerg-krause]

@moodeaudio I am patching MPD 0.19.21 (MPD 0.20 does not compile for ARMv5 with GCC <7):

From 0cb2f94eee584ea097d87942f6878181714d1bfe Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?J=C3=B6rg=20Krause?= <joerg.krause@embedded.rocks>
Date: Sat, 11 Mar 2017 10:29:52 +0100
Subject: [PATCH] input/curl: add low speed options
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Signed-off-by: Jörg Krause <joerg.krause@embedded.rocks>
---
 src/input/plugins/CurlInputPlugin.cxx | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/src/input/plugins/CurlInputPlugin.cxx b/src/input/plugins/CurlInputPlugin.cxx
index 3aa3b0018..4a3946fdd 100644
--- a/src/input/plugins/CurlInputPlugin.cxx
+++ b/src/input/plugins/CurlInputPlugin.cxx
@@ -760,6 +760,8 @@ CurlInputStream::InitEasy(Error &error)
    curl_easy_setopt(easy, CURLOPT_NOPROGRESS, 1l);
    curl_easy_setopt(easy, CURLOPT_NOSIGNAL, 1l);
    curl_easy_setopt(easy, CURLOPT_CONNECTTIMEOUT, 10l);
+   curl_easy_setopt(easy, CURLOPT_LOW_SPEED_LIMIT, 1l);
+   curl_easy_setopt(easy, CURLOPT_LOW_SPEED_TIME, 4l);

    if (proxy != nullptr)
        curl_easy_setopt(easy, CURLOPT_PROXY, proxy);
-- 
2.12.0

[moodeaudio]

@joerg-krause, Quick look at the input plugins doc and it indicates that options in ~/.curlrc should be in effect. https://www.musicpd.org/doc/user/input_plugins.html

[moodeaudio]

@joerg-krause, looking through the 0.20.6 and curl sources just to get very basic understanding of how options are handled and it appears that MPD checks a specific set of four proxy options in the curl block in mpd.conf, then sets some other options in CurlInputStream::InitEasy(). I'm not seeing where .curlrc is referenced. That may explain why my .curlrc settings are not effective.

CurlInputStream::InitEasy() { request = new CurlRequest(curl_global, GetURI(), this);

request->SetOption(CURLOPT_HTTP200ALIASES, http_200_aliases);
request->SetOption(CURLOPT_FOLLOWLOCATION, 1l);
request->SetOption(CURLOPT_MAXREDIRS, 5l);
request->SetOption(CURLOPT_FAILONERROR, 1l);

. . .

[pdgendt]

Since this sounds similar to an issue that we're having, I would like to add a comment here.

MPD version 0.20.4

When leaving a stream open for a very long time (multiple days) we also see that after a while there is no audio audible anymore, even though MPD shows that the status is playing. I can't say that we have heard the stuttering like the example file posted in the issue as we can't listen to it 24/7.

What we do see is that, even though MPD has the status PLAY, the elapsed seconds doesn't update anymore. Maybe this helps at pinpointing the problem? Also we never had this issue with MPD 0.19.17.

[victor910]

hi, I have a similar problem: May 03 11:34 : client: process command "playid "14"" May 03 11:34 : playlist: play 2:"http://prem3.radiotunes.com:80/rtdowntempolounge_hi?fdae1 cea24c8946ac5fd733f" May 03 11:34 : exception: Failed to decode http://prem3.radiotunes.com:80/rtdowntempoloung e_hi?fdae1cea24c8946ac5fd733f May 03 11:34 : exception: nested: CURL failed: Operation timed out after 10010 millisecond s with 0 out of 0 bytes received May 03 11:34 : player: played "http://prem3.radiotunes.com:80/rtdowntempolounge_hi?fdae1ce a24c8946ac5fd733f" May 03 11:34 : exception: Failed to decode http://prem3.radiotunes.com:80/rtdowntempoloung e_hi?fdae1cea24c8946ac5fd733f May 03 11:34 : exception: nested: CURL failed: Operation timed out after 10010 millisecond s with 0 out of 0 bytes received May 03 11:34 : client: command returned 2

my MPD: root@music:/var/log/mpd# mpd -V Music Player Daemon 0.20.19

Copyright (C) 2003-2007 Warren Dukes warren.dukes@gmail.com Copyright 2008-2017 Max Kellermann max.kellermann@gmail.com This is free software; see the source for copying conditions. There is NO warranty; not even MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

Database plugins: simple proxy upnp

Storage plugins: local smbclient nfs curl

Neighbor plugins: smbclient upnp

Decoders plugins: [mad] mp3 mp2 [mpg123] mp3 [vorbis] ogg oga [oggflac] ogg oga [flac] flac [opus] opus ogg oga [sndfile] wav aiff aif au snd paf iff svx sf voc w64 pvf xi htk caf sd2 [audiofile] wav au aiff aif [dsdiff] dff [dsf] dsf [faad] aac [mpcdec] mpc [wavpack] wv [modplug] 669 amf ams dbm dfm dsm far it med mdl mod mtm mt2 okt s3m stm ult umx xm [mikmod] amf dsm far gdm imf it med mod mtm s3m stm stx ult uni xm [sidplay] sid mus str prg P00 [wildmidi] mid [fluidsynth] mid [adplug] amd d00 hsc laa rad raw sa2 [ffmpeg] 16sv 3g2 3gp 4xm 8svx aa3 aac ac3 adx afc aif aifc aiff al alaw amr anim apc ape asf atrac au aud avi avm2 avs bap bfi c93 cak cin cmv cpk daud dct divx dts dv dvd dxa eac3 film flac flc fli fll flx flv g726 gsm gxf iss m1v m2v m2t m2ts m4a m4b m4v mad mj2 mjpeg mjpg mka mkv mlp mm mmf mov mp+ mp1 mp2 mp3 mp4 mpc mpeg mpg mpga mpp mpu mve mvi mxf nc nsv nut nuv oga ogm ogv ogx oma ogg omg opus psp pva qcp qt r3d ra ram rl2 rm rmvb roq rpl rvc shn smk snd sol son spx str swf tak tgi tgq tgv thp ts tsp tta xa xvid uv uv2 vb vid vob voc vp6 vmd wav webm wma wmv wsaud wsvga wv wve [gme] ay gbs gym hes kss nsf nsfe sap spc vgm vgz [pcm]

Filters: libsamplerate soxr

Tag plugins: id3tag

Output plugins: shout null fifo pipe alsa roar ao oss openal pulse jack httpd recorder

Encoder plugins: null vorbis opus lame wave flac

Archive plugins: [bz2] bz2 [zzip] zip [iso] iso

Input plugins: file alsa archive curl ffmpeg smbclient nfs mms cdio_paranoia

Playlist plugins: extm3u m3u pls xspf asx rss soundcloud flac cue embcue

Protocols: file:// http:// https:// mms:// mmsh:// mmst:// mmsu:// gopher:// rtp:// rtsp:// rtmp:// rtmpt:// rtmps:// smb:// nfs:// cdda:// alsa://

Other features: avahi epoll icu inotify ipv6 systemd tcp un

How to fixed?