Musc fails to play with proxy setting after upgrading MPD

[ian-s-mcb]

Bug report

Describe the bug

After updating MPD (from version 0.22.11 to 0.23), music fails to play without an error message when using the same network proxy settings (NFS) that previously worked, except under strange situations (which I'll explain later on).

Expected Behavior

Since I'm using MPD's proxy feature, I have two MPD servers. I find it confusing to called one of them remote and the other local, so I'll refer to the centralized MPD/NFS server as "MPD-a" and the remote MPD server / NFS client as "MPD-b".

The expected behavior is that music playback on MPD-b starts after running the following MPC commands (see the Log section) to clear, find, findadd, and play a music file.

Actual Behavior

MPC reports that playback has started, but track progress stays at 0%, no music plays, and no error message is logged.

Version

MPD-a and MPD-b are running on up-to-date, Arch Linux / Sway machines, with the followng kernel, Sway, and MPD versions.

$ uname -r
5.14.12-arch1-1

$ sway --version
sway version 1.6.1

$ mpd --version
Music Player Daemon 0.23 (0.23)
Copyright 2003-2007 Warren Dukes <warren.dukes@gmail.com>
Copyright 2008-2021 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 udisks nfs curl

Neighbor plugins:
 upnp udisks

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
 [hybrid_dsd] m4a
 [faad] aac
 [mpcdec] mpc
 [wavpack] wv
 [openmpt] mptm mod s3m xm it 669 amf ams c67 dbm digi dmf dsm dtm far imf ice j2b m15 mdl med mms mt2 mtm nst okt plm psm pt36 ptm sfx sfx2 st26 stk stm stp ult wow gdm mo3 oxm umx xpk ppm mmcmp
 [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
 [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 rtp:// rtsp:// rtsps://
 [gme] ay gbs gym hes kss nsf nsfe rsn sap spc vgm vgz
 [pcm]

Filters:
 libsamplerate soxr

Tag plugins:
 id3tag

Output plugins:
 shout null fifo pipe alsa ao oss openal solaris pipewire pulse jack httpd snapcast recorder

Encoder plugins:
 null vorbis opus lame twolame wave flac

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

Input plugins:
 file io_uring archive alsa qobuz curl ffmpeg nfs mms cdio_paranoia

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

Protocols:
 file:// alsa:// cdda:// ftp:// ftps:// gopher:// hls+http:// hls+https:// http:// https:// mms:// mmsh:// mmst:// mmsu:// nfs:// qobuz:// rtmp:// rtmpe:// rtmps:// rtmpt:// rtmpte:// rtmpts:// rtp:// rtsp:// rtsps:// scp:// sftp:// smb:// srtp://

Other features:
 avahi dbus udisks epoll icu inotify ipv6 systemd tcp un

MPD config

MPD-a (hostname: hurray)

# ~/.config/mpd/mpd.conf
music_directory "~/.config/mpd/music"
playlist_directory "~/.config/mpd/playlists"
db_file "~/.config/mpd/database"
log_file "syslog"
pid_file "~/.config/mpd/pid" 
state_file "~/.config/mpd/state"
state_file_interval "1"
sticker_file "~/.config/mpd/sticker.sql" 
port "6600"
log_level "default"
auto_update "yes"
default_permissions "read,add,control,admin"
input {
 plugin "curl"
}
audio_output {
 type "pulse"
 name "pulse audio"
}
filesystem_charset "UTF-8"
max_output_buffer_size "20480"
decoder {
 plugin "wildmidi"
 enabled "no"
}

MPD-a file permissions and music folder

$ ls -l .config/mpd/
total 1420
-rw-r--r-- 1 ian ian 1391384 Oct 17 20:45 database
-rw-r--r-- 1 ian ian   13198 Oct 23  2020 mpd.away.conf
-rw-r--r-- 1 ian ian     537 Oct 18 17:44 mpd.conf
-rw-r--r-- 1 ian ian   13254 Dec 26  2020 mpd.home.conf
lrwxrwxrwx 1 ian ian      15 Mar 12  2021 music -> /home/ian/music
-rw-r--r-- 1 ian ian       5 Oct 19 14:35 pid
drwxr-xr-x 2 ian ian    4096 Jun 12  2020 playlists
-rw-r--r-- 1 ian ian     840 Oct 19 14:29 state
-rw-r--r-- 1 ian ian   12288 May 18  2020 sticker.sql
$ ls -l ~ | grep music
lrwxrwxrwx 1 ian ian   15 May  1 01:11 music -> /mnt/nas/music/
$ ls -l /mnt/nas/music/
total 52
drwx------   2 ian ian 16384 May 20  2020 lost+found
drwxr-xr-x   4 ian ian  4096 Aug 27 14:02 music-current
drwxr-xr-x 473 ian ian 20480 Aug  4 13:13 music-full
drwxr-xr-x   5 ian ian  4096 Dec 23  2020 music-mixes
drwxr-xr-x   3 ian ian  4096 Sep 29 21:08 music-song-picks
drwxr-xr-x   5 ian ian  4096 Jan  7  2019 other

MPD-b (hostname: egads)

# ~/.config/mpd/mpd.conf
music_directory "nfs://hurray/mnt/nas/music"
playlist_directory "~/.config/mpd/playlists"
log_file "syslog"
pid_file "~/.config/mpd/pid" 
state_file "~/.config/mpd/state"
state_file_interval "1"
sticker_file "~/.config/mpd/sticker.sql" 
port "6600"
log_level "default"
auto_update "yes"
default_permissions "read,add,control,admin"
database {
 plugin "proxy"
 host "hurray"
}
input {
 plugin "curl"
}
audio_output {
 type "pulse"
 name "pulse audio"
}
filesystem_charset "UTF-8"
max_output_buffer_size "20480"
decoder {
 plugin "wildmidi"
 enabled "no"
}

NFS shares

The settings on MPD-a (the NFS server, hostname: hurray) allow read-write access to world.

$ sudo exportfs -v
# [..trimmed output...]
/mnt/nas/music  <world>(sync,wdelay,hide,no_subtree_check,sec=sys,rw,insecure,root_squash,no_all_squash)

Shares can be successfully mounted on MPD-b (hostname: egads).

$ mount /mnt/nas/music
$ findmnt /mnt/nas/music
TARGET         SOURCE                FSTYPE OPTIONS
/mnt/nas/music hurray:/mnt/nas/music nfs4   rw,nosuid,nodev,noexec,relatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,clientaddr=192.168.1.102,local_lock=none,addr=192.168.1.105
$ ls /mnt/nas/music/music-full/ZOX/2002\ -\ Take\ Me\ Home/
'01 The Squid.mp3'  '03 Ghostown.mp3'  '07 Rain on Me.mp3'  '13 Canon.mp3'

Log

MPC commands

Run on MPD-b

$ mpc clear
$ mpc find '((artist == "ZOX") AND (title == "Canon"))'
music-full/ZOX/2002 - Take Me Home/13 Canon.mp3
$ mpc findadd '((artist == "ZOX") AND (title == "Canon"))'
$ mpc play
ZOX - Canon
[playing] #1/1   0:00/4:46 (0%)
volume: n/a   repeat: off   random: off   single: off   consume: off
$ mpc status
ZOX - Canon
[playing] #1/1   0:00/4:46 (0%)
volume: n/a   repeat: off   random: off   single: off   consume: off
$ mpc status
ZOX - Canon
[playing] #1/1   0:00/4:46 (0%)
volume: n/a   repeat: off   random: off   single: off   consume: off

MPD processes

Run on MPD-a

$ mpd --stderr --no-daemon --verbose
config_file: loading file /home/ian/.config/mpd/mpd.conf
server_socket: 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.7
opus: libopus 1.3.1
sndfile: libsndfile-1.0.31
hybrid_dsd: The Hybrid DSD decoder is disabled because it was not explicitly enabled
simple_db: reading DB
input: Input plugin 'qobuz' is not configured: %s
curl: version 7.79.1
curl: with OpenSSL/1.1.1l
state_file: Loading state file /home/ian/.config/mpd/state
event: RTIOThread could not get realtime scheduling, continuing anyway: %s
inotify: initializing inotify
inotify: watching music directory
client: [0] opened from [::1]:36842
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "plchanges "0""
client: [0] command returned 0
client: [0] process command "outputs"
client: [0] command returned 0
client: [0] process command "decoders"
client: [0] command returned 0
client: [0] process command "outputs"
client: [0] command returned 0
client: [0] process command "outputs"
client: [0] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [1] opened from 192.168.1.102:35374
client: [1] process command "idle database"
client: [1] command returned 1
client: [1] process command "find "((Artist == \"ZOX\") AND (Title == \"Canon\"))" window 0:4096"
client: [1] command returned 0
client: [1] process command "idle database"
client: [1] command returned 1
client: [1] process command "find "((Artist == \"ZOX\") AND (Title == \"Canon\"))" window 0:4096"
client: [1] command returned 0
client: [1] process command "idle database"
client: [1] command returned 1

Run on MPD-b

$ mpd --stderr --no-daemon --verbose
config_file: loading file /home/ian/.config/mpd/mpd.conf
server_socket: 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.7
opus: libopus 1.3.1
sndfile: libsndfile-1.0.31
hybrid_dsd: The Hybrid DSD decoder is disabled because it was not explicitly enabled
input: Input plugin 'qobuz' is not configured: %s
curl: version 7.79.1
curl: with OpenSSL/1.1.1l
event: RTIOThread could not get realtime scheduling, continuing anyway: %s
state_file: Loading state file /home/ian/.config/mpd/state
client: [0] opened from [::1]:43456
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "plchanges "0""
client: [0] command returned 0
client: [0] process command "outputs"
client: [0] command returned 0
client: [0] process command "decoders"
client: [0] command returned 0
client: [0] process command "outputs"
client: [0] command returned 0
client: [0] process command "outputs"
client: [0] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [1] opened from [::1]:43458
client: [1] process command "status"
client: [1] command returned 0
client: [1] process command "plchanges "0""
client: [1] command returned 0
client: [1] process command "outputs"
client: [1] command returned 0
client: [1] process command "decoders"
client: [1] command returned 0
client: [1] process command "outputs"
client: [1] command returned 0
client: [1] process command "outputs"
client: [1] command returned 0
client: [1] process command "idle"
client: [1] command returned 1
client: [2] opened from [::1]:43460
client: [2] process command "clear"
client: [2] command returned 0
client: [2] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [2] process command list returned 0
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [2] closed
client: [0] process command "plchanges "2""
client: [0] command returned 0
client: [1] process command "plchanges "2""
client: [1] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "idle"
client: [1] command returned 1
client: [3] opened from [::1]:43462
client: [3] process command list
client: process command "tagtypes "clear""
client: command returned 0
client: process command "find "((artist == \"ZOX\") AND (title == \"Canon\"))""
client: command returned 0
client: [3] process command list returned 0
client: [3] closed
client: [4] opened from [::1]:43464
client: [4] process command "findadd "((artist == \"ZOX\") AND (title == \"Canon\"))""
client: [4] command returned 0
client: [4] closed
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [1] process command "plchanges "3""
client: [1] command returned 0
client: [0] process command "plchanges "3""
client: [0] command returned 0
client: [1] process command "idle"
client: [1] command returned 1
client: [0] process command "idle"
client: [0] command returned 1
client: [5] opened from [::1]:43466
client: [5] process command "play"
playlist: play 0:"music-full/ZOX/2002 - Take Me Home/13 Canon.mp3"
client: [5] command returned 0
client: [5] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [5] process command list returned 0
client: [5] closed
client: [6] opened from [::1]:43468
client: [6] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [6] process command list returned 0
client: [6] closed
client: [7] opened from [::1]:43470
client: [7] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [7] process command list returned 0
client: [7] closed
state_file: Saving state file /home/ian/.config/mpd/state

Strange situations where MPD partially works

This really bizarre, but MPD succeeds in playing one, and only one, song when the following is performed. After that song is played, the steps need to be rerun in order to play another song. The steps appear to work for any song in my library. I can't comment on why this has an effect, but I noticed it and thought I might as well mention it.

Steps (assuming there already is song queued up):

1. Run mpc stop
2. Press the ncmpcpp play keybinding (song still won't play)
3. Run mpc play (song still won't play)
4. Run the Firefox or Chromium executable from the command line or via Sway keybinding (finally, the song will now play)

Here is the MPD-b log during those steps:

client: [8] opened from [::1]:43472
client: [8] process command "stop"
playlist: stop
player: played "music-full/ZOX/2002 - Take Me Home/13 Canon.mp3"
client: [8] command returned 0
client: [8] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [8] process command list returned 0
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [8] closed
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "idle"
client: [1] command returned 1
state_file: Saving state file /home/ian/.config/mpd/state
client: [0] process command "playid "1""
playlist: play 0:"music-full/ZOX/2002 - Take Me Home/13 Canon.mp3"
client: [0] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [9] opened from [::1]:43474
client: [9] process command "play"
client: [9] command returned 0
client: [9] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [9] process command list returned 0
client: [9] closed
decoder_thread: probing plugin mad
decoder: audio_format=44100:24:2, seekable=true
output: OutputThread could not get realtime scheduling, continuing anyway: %s
output: opened "pulse audio" (pulse) audio_format=44100:24:2
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [1] process command "status"
client: [1] command returned 0
client: [1] process command "idle"
client: [1] command returned 1
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "plchanges "4""
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [1] process command "idle"
client: [1] command returned 1
client: [0] process command "plchanges "4""
client: [0] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "idle"
client: [1] command returned 1
client: [1] process command "status"
client: [1] command returned 0
client: [1] process command "idle"
client: [1] command returned 1
state_file: Saving state file /home/ian/.config/mpd/state
client: [0] process command "status"
client: [0] command returned 0
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "idle"
client: [1] command returned 1
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [1] process command "idle"
client: [1] command returned 1
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "idle"
client: [1] command returned 1
client: [0] process command "status"
client: [0] command returned 0
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "idle"
client: [1] command returned 1
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [1] process command "idle"
client: [1] command returned 1
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [1] process command "idle"
client: [1] command returned 1
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [1] process command "idle"
client: [1] command returned 1
client: [0] process command "idle"
client: [0] command returned 1
client: [0] process command "status"
client: [0] command returned 0
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "idle"
client: [1] command returned 1
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [1] process command "idle"
client: [1] command returned 1
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "idle"
client: [1] command returned 1
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "idle"
client: [1] command returned 1
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "idle"
client: [1] command returned 1
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "idle"
client: [1] command returned 1
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [1] process command "idle"
client: [1] command returned 1
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [1] process command "idle"
client: [1] command returned 1
client: [0] process command "idle"
client: [0] command returned 1
client: [0] process command "status"
client: [0] command returned 0
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
client: [1] process command "idle"
client: [1] command returned 1
client: [10] opened from [::1]:43476
client: [10] process command "stop"
playlist: stop
player: played "music-full/ZOX/2002 - Take Me Home/13 Canon.mp3"
output: closed "pulse audio" (pulse)
client: [10] command returned 0
client: [10] process command list
client: process command "status"
client: command returned 0
client: process command "currentsong"
client: command returned 0
client: [10] process command list returned 0
client: [1] process command "status"
client: [1] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [10] closed
client: [1] process command "idle"
client: [1] command returned 1
client: [0] process command "idle"
client: [0] command returned 1
state_file: Saving state file /home/ian/.config/mpd/state

[ian-s-mcb]

Excellent. Works like a charm now. Thank you!