"do not use RAW PCM" + "PCM - 16" bit still crashes mpd after a couple of seconds. This time (on a different pi) with a new error:
This pi is a Pi zero 2 W with a HiFiBerry DAC+ Zero. The one I had tested on so far was a Pi 3B with a HiFiBerry DAC+ Pro (I wanted to rule out the hardware).
Mar 06 17:54 : exception: CURL failed: transfer closed with 34696704 bytes remaining to read
Mar 06 17:54 : decoder_thread: probing plugin pcm
Mar 06 17:54 : decoder: audio_format=44100:16:2, seekable=true
Mar 06 17:54 : client: [12] process command "status"
Mar 06 17:54 : client: [12] command returned 0
Mar 06 17:54 : client: [12] process command "currentsong"
Mar 06 17:54 : client: [12] command returned 0
Mar 06 17:54 : client: [12] process command "playlistinfo "1""
Mar 06 17:54 : client: [12] command returned 0
Mar 06 17:54 : client: [12] process command "status"
Mar 06 17:54 : client: [12] command returned 0
Mar 06 17:54 : client: [12] process command "currentsong"
Mar 06 17:54 : client: [12] command returned 0
Mar 06 17:54 : client: [12] process command "playlistinfo "1""
Mar 06 17:54 : client: [12] command returned 0
Mar 06 17:54 : client: [12] process command "status"
Mar 06 17:54 : client: [12] command returned 0
Mar 06 17:54 : client: [12] process command "currentsong"
Mar 06 17:54 : client: [12] command returned 0
Mar 06 17:54 : client: [12] process command "playlistinfo "1""
Mar 06 17:54 : client: [12] command returned 0
Mar 06 17:54 : client: [12] process command "status"
Mar 06 17:54 : client: [12] command returned 0
Mar 06 17:54 : client: [12] process command "currentsong"
Mar 06 17:54 : client: [12] command returned 0
Mar 06 17:54 : client: [12] process command "playlistinfo "1""
Mar 06 17:54 : client: [12] command returned 0
Mar 06 17:54 : client: [12] process command "status"
Mar 06 17:54 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Setting "force little endian for PCM streams" and "PCM - 24 bit" still yields noise for a few seconds and then crashes mpd.
Plugin log:
796971; 95 ForcedEncode - Stream is being encoded to apply Replaygain/DSP settings.
796975; 96 Play - Z:\M4\Pixies\You’re So Impatient [Single]\02 Que Sera Sera.flac (http://192.168.1.5:49382/encode/5B95923D2C4EC020-2147483617.L24)
797235; 97 StateTimer - Playing,old=Stopped
797245; 98 Profile - Generic Device, useragent=Music Player Daemon 0.23.12
797255; 100 Profile - Generic Device, useragent=Music Player Daemon 0.23.12
797262; 101 GetEncodedFile[15] 192.168.1.5 - GET Z:\M4\Pixies\You’re So Impatient [Single]\02 Que Sera Sera.flac to 192.168.1.30; mime=audio/L24;rate=44100;channels=2,rate=44100,channels=2
797252; 99 ForcedEncode - Stream is being encoded to apply Replaygain/DSP settings.
797751; 102 SetNextAVTransportURI - Success - http://192.168.1.5:49382/encode/3ADE7E64C55A1DC90.L24
802559; 103 GetEncodedFile[15] - exit=0, playtime=5286
817075; 104 PostSoapRequest - 500,send=POST /uuid-d42bb9f2-5808-dbd2-61e3-2ccf67a5792c/ctl-urn-schemas-upnp-org-service-AVTransport-1 HTTP/1.1
Host: 192.168.1.30:49152
User-Agent: MusicBee UPnP Plugin
Content-Type: text/xml; charset="utf-8"
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#Pause"
Content-Length: 290
<?xml version="1.0" encoding="UTF-8"?><s:Envelope s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/" xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"><s:Body><u:Pause xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"><InstanceID>0</InstanceID></u:Pause></s:Body></s:Envelope>
817080; 105 SoapRequest:Pause:urn:schemas-upnp-org:service:AVTransport:1:InstanceID=0 - <?xml version="1.0"?>
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
<s:Body>
<s:Fault>
<faultcode>s:Client</faultcode>
<faultstring>UPnPError</faultstring>
<detail>
<UPnPError xmlns="urn:schemas-upnp-org:control-1-0">
<errorCode>501</errorCode>
<errorDescription>Action Failed</errorDescription>
</UPnPError>
</detail>
</s:Fault>
</s:Body>
</s:Envelope>
817083; 106 Pause - status=500
mpd log:
Mar 06 17:58 : client: [6] process command "addid "http://192.168.1.5:49382/encode/5B95923D2C4EC020-2147483617.L24" "0""
Mar 06 17:58 : client: [6] command returned 0
Mar 06 17:58 : client: [6] process command "addtagid "3" "Artist" "Pixies""
Mar 06 17:58 : client: [6] command returned 0
Mar 06 17:58 : client: [6] process command "addtagid "3" "Album" "You're So Impatient [Single]""
Mar 06 17:58 : client: [6] command returned 0
Mar 06 17:58 : client: [6] process command "addtagid "3" "Title" "Que Sera Sera""
Mar 06 17:58 : client: [6] command returned 0
Mar 06 17:58 : client: [6] process command "addtagid "3" "Track" "2""
Mar 06 17:58 : client: [6] command returned 0
Mar 06 17:58 : client: [6] process command "addtagid "3" "Comment" "client=upmpdcli;""
Mar 06 17:58 : client: [6] command returned 0
Mar 06 17:58 : client: [6] process command "status"
Mar 06 17:58 : client: [6] command returned 0
Mar 06 17:58 : client: [6] process command "status"
Mar 06 17:58 : client: [6] command returned 0
Mar 06 17:58 : client: [6] process command "stop"
Mar 06 17:58 : client: [6] command returned 0
Mar 06 17:58 : client: [6] process command "playlistinfo"
Mar 06 17:58 : client: [6] command returned 0
Mar 06 17:58 : client: [6] process command "play"
Mar 06 17:58 : playlist: play 0:"http://192.168.1.5:49382/encode/5B95923D2C4EC020-2147483617.L24"
Mar 06 17:58 : client: [6] command returned 0
Mar 06 17:58 : client: [6] process command "status"
Mar 06 17:58 : client: [6] command returned 0
Mar 06 17:58 : client: [6] process command "currentsong"
Mar 06 17:58 : client: [6] command returned 0
Mar 06 17:58 : client: [6] process command "playlistinfo "1""
Mar 06 17:58 : client: [6] command returned 0
Mar 06 17:58 : decoder_thread: probing plugin pcm
Mar 06 17:58 : decoder: audio_format=44100:24:2, seekable=true
Mar 06 17:58 : alsa_output: opened hw:CARD=sndrpihifiberry,DEV=0 type=HW
Mar 06 17:58 : alsa_output: buffer: size=64..65536 time=1451..1486078
Mar 06 17:58 : alsa_output: period: size=32..32768 time=725..743039
Mar 06 17:58 : alsa_output: default period_time = buffer_time/4 = 500000/4 = 125000
Mar 06 17:58 : alsa_output: format=S24_LE (Signed 24 bit Little Endian)
Mar 06 17:58 : alsa_output: buffer_size=22050 period_size=4410
Mar 06 17:58 : output: opened "Hifiberry DAC" (alsa) audio_format=44100:24:2
Mar 06 17:58 : alsa_output: Decoder is too slow; playing silence to avoid xrun
Using flac as the encoder also plays the first song for a couple seconds and then crashes mpd. According to the log it instantly tried to play the 2nd queued track before getting stuck. Changing the flac encoder to the
latest version also yielded no difference.
Plugin log:
1543441; 155 ForcedEncode - Stream is being encoded to apply Replaygain/DSP settings.
1543444; 156 Play - Z:\M4\Great Lake Swimmers\In Pieces- An Acoustic Retrospective\16 Riverine.flac (http://192.168.1.5:49382/encode/9B671606869A561C-2147483565.flac)
1543489; 157 Profile - Generic Device, useragent=Music Player Daemon 0.23.12
1543493; 158 Profile - Generic Device, useragent=Music Player Daemon 0.23.12
1543496; 159 GetEncodedFile[23] 192.168.1.5 - GET Z:\M4\Great Lake Swimmers\In Pieces- An Acoustic Retrospective\16 Riverine.flac to 192.168.1.30; mime=audio/flac,rate=44100,channels=2
1543846; 160 StateTimer - Playing,old=Paused
1543862; 161 ForcedEncode - Stream is being encoded to apply Replaygain/DSP settings.
1544967; 162 SetNextAVTransportURI - Success - http://192.168.1.5:49382/encode/BBE0A499E270767A0.flac
1545841; 163 GetEncodedFile[23] - exit=0, playtime=2340
1622567; 164 PostSoapRequest - 500,send=POST /uuid-d42bb9f2-5808-dbd2-61e3-2ccf67a5792c/ctl-urn-schemas-upnp-org-service-AVTransport-1 HTTP/1.1
Host: 192.168.1.30:49152
User-Agent: MusicBee UPnP Plugin
Content-Type: text/xml; charset="utf-8"
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#Pause"
Content-Length: 290
<?xml version="1.0" encoding="UTF-8"?><s:Envelope s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/" xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"><s:Body><u:Pause xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"><InstanceID>0</InstanceID></u:Pause></s:Body></s:Envelope>
1622584; 165 SoapRequest:Pause:urn:schemas-upnp-org:service:AVTransport:1:InstanceID=0 - <?xml version="1.0"?>
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
<s:Body>
<s:Fault>
<faultcode>s:Client</faultcode>
<faultstring>UPnPError</faultstring>
<detail>
<UPnPError xmlns="urn:schemas-upnp-org:control-1-0">
<errorCode>501</errorCode>
<errorDescription>Action Failed</errorDescription>
</UPnPError>
</detail>
</s:Fault>
</s:Body>
</s:Envelope>
1622587; 166 Pause - status=500
mpd log:
Mar 06 18:11 : player: played "http://192.168.1.5:49382/files/867779E74D38F64Ap.flac"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "status"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "playlistinfo"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "clear"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "repeat "0""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "random "0""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "single "0""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "consume "0""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "addid "http://192.168.1.5:49382/encode/9B671606869A561C-2147483565.flac" "0""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "addtagid "3" "Artist" "Great Lake Swimmers""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "addtagid "3" "Album" "In Pieces: An Acoustic Retrospective""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "addtagid "3" "Title" "Riverine""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "addtagid "3" "Track" "16""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "addtagid "3" "Comment" "client=upmpdcli;""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "status"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "stop"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "play"
Mar 06 18:11 : playlist: play 0:"http://192.168.1.5:49382/encode/9B671606869A561C-2147483565.flac"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "status"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "currentsong"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "playlistinfo "1""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : decoder_thread: probing plugin flac
Mar 06 18:11 : decoder: audio_format=44100:16:2, seekable=true
Mar 06 18:11 : alsa_output: opened hw:CARD=sndrpihifiberry,DEV=0 type=HW
Mar 06 18:11 : alsa_output: buffer: size=64..65536 time=1451..1486078
Mar 06 18:11 : alsa_output: period: size=32..32768 time=725..743039
Mar 06 18:11 : alsa_output: default period_time = buffer_time/4 = 500000/4 = 125000
Mar 06 18:11 : alsa_output: format=S24_LE (Signed 24 bit Little Endian)
Mar 06 18:11 : alsa_output: buffer_size=22050 period_size=4410
Mar 06 18:11 : output: opened "Hifiberry DAC" (alsa) audio_format=44100:24:2
Mar 06 18:11 : output: converting in=44100:16:2 -> f=44100:24:2 -> out=44100:24:2
Mar 06 18:11 : client: [8] process command "repeat "0""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "random "0""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "single "0""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "consume "0""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "addid "http://192.168.1.5:49382/encode/BBE0A499E270767A0.flac" "1""
Mar 06 18:11 : playlist: queue song 1:"http://192.168.1.5:49382/encode/BBE0A499E270767A0.flac"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "addtagid "4" "Artist" "Laswell, Greg, Greg Laswell""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "addtagid "4" "Album" "Covers [EP]""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "addtagid "4" "Title" "The Killing Moon""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "addtagid "4" "Track" "1""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "addtagid "4" "Comment" "client=upmpdcli;""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "status"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "currentsong"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "playlistinfo "1""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [7] process command "idle playlist player mixer options"
Mar 06 18:11 : client: [7] command returned 1
Mar 06 18:11 : client: [8] process command "status"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "currentsong"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "playlistinfo "1""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "status"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "currentsong"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "playlistinfo "1""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "playlistinfo"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [7] process command "idle playlist player mixer options"
Mar 06 18:11 : client: [7] command returned 1
Mar 06 18:11 : client: [8] process command "status"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "currentsong"
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "playlistinfo "1""
Mar 06 18:11 : client: [8] command returned 0
Mar 06 18:11 : client: [8] process command "status"
Mar 06 18:11 : alsa_output: Decoder is too slow; playing silence to avoid xrun
After some googling I tried increasing the buffer time and period time of the audio device as
suggested here, but this did not resolve the issue. Someone else in the same thread thinks it's a general problem with the
curl implementation of mpd.
So I guess the problem might lie there instead of in the plugin.
Setting "force native stream (global setting)" leads to gapless playback with no crashes so far. Although, as simbun has noted, MusicBee is not in sync with the playback progress on the upnp player, which is obvious when you have synced lyrics displayed while playing. In my case it lags behind the music 0,5-1 seconds and so far does not seem to drift over time (at least over the course of 2 test songs 3min each).
Btw. at least for me, the removal of the NextAVTransportURI when the "Upcoming Tracks" are edited in MusicBee doesn't work yet. I queued 2 tracks and instantly removed the second one from the queue. The upnp player still starts playing it when the first track ends while MusicBee is stuck "playing" without a wavebar and still has the 1st song active.