Satellite mode with NFSv4 server results in infinite loop

Question

Satellite mode with NFSv4 server results in infinite loop

EdwinKM opened this issue 7 months ago · 5 comments

Bug report

Describe the bug

Recently libnfs URL arguments support is added.
commit: 9384bff
feature request: #2039

I have a weird issue which i can not reproduce with NFSv3.
Basically the second album (which is never opened by the MPD satellite server) results in a loop for both the MPD server and MPD client.

NOTE: My satellite MPD server (nas) is never restarted. It is also not using NFS loopback (direct mount of the music)
Only my MPD client is manually compiled and the MPD server is the Debian Unstable package running in a TrueNAS Scale container.

I use Cantata and in the "Library" i have 4 albums:

1
2
3
4

I start the satellite MPD client and Cantata connects to this client

Play album 1 -> works
Play album 2 -> loop
kill MPD client (loop stops for both)

I start the satellite MPD client and Cantata connects to this client

Play album 1 -> works
Play album 2 -> works
Play album 3 -> loop
kill MPD client (loop stops for both)

So, after the server once entered the "loop" the client works correct the next instance.

Expected Behavior

Switch to other second album without problems.

Actual Behavior

It plays the song of the second album. But things break:

server log starts looping
client log starts looping
Cantata client does not respond anymore, only progress seems to keep updating

Version

edwin@debian:~/MPD/output/release$ ./mpd --version
Music Player Daemon 0.24 (v0.23.15-1321-g9384bff6f)
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

Decoder plugins:
 [mpg123] mp3
 [mad] mp3 mp2
 [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
 [wildmidi] mid
 [fluidsynth] mid
 [adplug] amd d00 hsc laa rad raw sa2
 [gme] ay gbs gym hes kss nsf nsfe rsn sap spc vgm vgz
 [ffmpeg] 264 265 302 3g2 3gp 4xm 669 722 aa aa3 aac aax ac3 ace acm act adf adp ads adx aea afc aiff aix al alias_pix alp amf amr amrnb amrwb ams anm ans apc ape apl apm apng aptx aptxhd aqt argo_asf argo_brp argo_cvg art asc asf asf_o ass ast au avc avi avif avr avs avs2 avs3 bcstm bethsoftvid bfi bfstm bin bink binka bit bitpacked bmp_pipe bmv boa brender_pix brstm c2 c93 caf cdata cdg cdxl cgi cif cine codec2raw concat cri_pipe dash dat data daud dav dbm dds_pipe dfa dff dfpwm dif digi dirac diz dmf dnxhd dpx_pipe dsf dsicin dsm dss dst dtk dtm dts dtshd dv dvbsub dvbtxt dxa ea eac3 exr_pipe f32be f32le f4v f64be f64le fap far ffmetadata film_cpk fits flac flic flm flv frm fsb fwse g722 g723_1 g726 g726le g729 gdm gdv gem_pipe genh gif gif_pipe gsm gxf h261 h263 h264 h265 h26l hca hcom hevc hls hnm ice ico idcin idf idx iff ifv ilbc image2 image2pipe imf imx ipmovie ipu ircam ism isma ismv iss it iv8 ivf ivr j2b j2k j2k_pipe jacosub jpeg_pipe jpegls_pipe jpegxl_pipe jv kux kvag libgme lmlm4 loas lrc lvf lxf m15 m2a m4a m4b m4v mac mca mcc mdl med mgsts microdvd mj2 mjpeg mjpg mk3d mka mks mkv mlp mlv mm mmcmp mmf mms mo3 mod mods moflex mov mp2 mp3 mp4 mpa mpc mpc8 mpeg mpegts mpegtsraw mpegvideo mpl2 mpo mptm msbc msf msnwctcp msp mt2 mtaf mtm mtv musx mv mvi mxf mxg nfo nist nsp nst nsv nut nuv obu ogg okt oma omg paf pam_pipe pbm_pipe pcx_pipe pfm_pipe pgm_pipe pgmyuv_pipe pgx_pipe phm_pipe photocd_pipe pictor_pipe pjs plm pmp png_pipe pp_bnk ppm ppm_pipe psd_pipe psm psp psxstr pt36 ptm pva pvf qcif qcp qdraw_pipe qoi_pipe r3d rco rcv rgb rl2 rm roq rpl rsd rso rt rtp rtsp s16be s24be s24le s32be s32le s337m s3m sami sap sb sbc sbg scc scd sdp sdr2 sds sdx ser sf sfx sfx2 sga sgi_pipe shn sln smi smk smush sol son sox spdif sph srt ss2 st26 stk stl stm stp str sub sunrast_pipe sup svag svg_pipe svs sw swf tak tco tedcaptions thd thp tiertexseq tiff_pipe tmv tta txd txt ty ty+ u16be u24be u24le u32be u32le ub ul ult umx uw v v210 vag vb vbn_pipe vc1 vidc viv vividas vmd voc vpk vqe vqf vql vt vtt w64 wav wc3movie webm webm_dash_manifest webp_pipe wow wsaud wsd wsvqa wtv wv wve xa xbin xbm_pipe xl xm xmv xpk xpm_pipe xvag xwd_pipe xwma y4m yop yuv yuv10 rtp:// rtsp:// rtsps://
 [pcm]

Filters:
 libsamplerate soxr

Tag plugins:
 id3tag

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

Encoder plugins:
 null vorbis opus lame twolame wave flac shine

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

Input plugins:
 file 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

Configuration

edwin@debian:~$ cat /usr/local/etc/mpd.conf |grep -v ^# |grep -v ^$
music_directory		"nfs://san/mnt/tank/music?version=4"
log_file			"~/mpd.log"
log_level			"warning"
auto_update	"no"
zeroconf_enabled		"no"
database {
  plugin "proxy"
  host "san"
  port "9999"
}
input {
        plugin "curl"
}
audio_output {
	type		"pulse"
	name		"Pulse Output"
}
filesystem_charset		"UTF-8"

Log

Included a diff picture between NFSv3 and NFSv4 for the MPD client log.

MPD Client

client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "clear"
playlist: stop
player: played "<PATH>/<FIRST_ALBUM>/<SONG_FIRST_ALBUM>.mp3"
output: closed "Pulse Output" (pulse)
client: [0] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command list
client: process command "add \"<SECOND_ALBUM>/<SONG_SECOND_ALBUM>.flac\""
client: command returned 0
client: [0] process command list returned 0
client: [0] process command "play 0"
playlist: play 0:"<SECOND_ALBUM>/<SONG_SECOND_ALBUM>.flac"
client: [0] command returned 0
client: [0] process command "currentsong"
client: [0] command returned 0
client: [0] process command "playlistinfo"
client: [0] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "replay_gain_status"
client: [0] command returned 0
client: [1] process command "idle"
client: [1] command returned 1
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 0"
decoder_thread: probing plugin flac
decoder: audio_format=44100:16:2, seekable=true
output: opened "Pulse Output" (pulse) audio_format=44100:16:2
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 8192"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 16384"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 24576"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 32768"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 40960"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 49152"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 57344"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 65536"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 73728"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 81920"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 90112"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 98304"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 106496"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 114688"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 122880"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 131072"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 139264"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 147456"
client: [0] command returned 0
...
...

MPD Server

client: [30] process command "find base "<SECOND_ALBUM>/<SONG_SECOND_ALBUM>.flac" window 0:4096"
client: [30] command returned 0
client: [30] process command "idle database"
client: [30] command returned 1
client: [30] process command "lsinfo "<SECOND_ALBUM>/""
exception: No such directory
client: [30] command returned 3
client: [30] process command "idle database"
client: [30] command returned 1
client: [30] process command "lsinfo "<SECOND_ALBUM>/""
exception: No such directory
client: [30] command returned 3
client: [30] process command "idle database"
client: [30] command returned 1
...
...

Compared with

MPD Client which work fine (NFSv3 server and NFSv3 config)

client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "clear"
playlist: stop
player: played "<FIRST_ALBUM>/<SONG_FIRST_ALBUM>.mp3"
output: closed "Pulse Output" (pulse)
client: [0] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command list
client: process command "add \"<SECOND_ALBUM>/<SONG_SECOND_ALBUM>.mp3\""
client: command returned 0
client: [0] process command list returned 0
client: [0] process command "play 0"
playlist: play 0:"<SECOND_ALBUM>/<SONG_SECOND_ALBUM>.mp3"
client: [0] command returned 0
client: [0] process command "currentsong"
client: [0] command returned 0
client: [0] process command "playlistinfo"
client: [0] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "replay_gain_status"
client: [0] command returned 0
client: [1] process command "idle"
client: [1] command returned 1
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 0"
decoder_thread: probing plugin mpg123
decoder: audio_format=44100:16:2, seekable=true
output: opened "Pulse Output" (pulse) audio_format=44100:16:2
client: [0] command returned 3
client: [0] process command "currentsong"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 0"
client: [0] command returned 3
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "plchangesposid \"6\""
client: [0] command returned 0
client: [1] process command "idle"
client: [1] command returned 1
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "plchangesposid \"7\""
client: [0] command returned 0
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "replay_gain_status"
client: [0] command returned 0
client: [1] process command "idle"
...
...

MPD Server which work fine (NFSv3 server and NFSv3 config)

client: [40] process command "find base "<SECOND_ALBUM>/<SONG_SECOND_ALBUM>.mp3" window 0:4096"
client: [40] command returned 0
client: [40] process command "idle database"
client: [40] command returned 1
client: [40] process command "lsinfo "<SECOND_ALBUM>/""
exception: No such directory
client: [40] command returned 3
client: [40] process command "idle database"
client: [40] command returned 1
client: [40] process command "lsinfo "<SECOND_ALBUM>/""
exception: No such directory
client: [40] command returned 3
client: [40] process command "idle database"
client: [40] command returned 1
client: [40] closed
...
...

Answer 1 · 2024-05-10T14:38:53.000Z

What does "looping" mean?

Answer 2 · 2024-05-10T15:32:05.000Z

What does "looping" mean?

The MPD client is continuously throwing messages, increasing the last number each time

client: [0] process command "albumart \"<SECOND_ALBUM>/\" 8192"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 16384"
client: [0] command returned 0
client: [0] process command "albumart \"<SECOND_ALBUM>/\" 24576"
client: [0] command returned 0

and the MPD server is continuously throwing messages

client: [30] process command "lsinfo "<SECOND_ALBUM>/""
exception: No such directory
client: [30] command returned 3
client: [30] process command "idle database"
client: [30] command returned 1

Both stop logging if i kill the MPD Client.

Answer 3 · 2024-05-10T15:36:50.000Z

This loop is caused by repeated commands received from your client. You have not explained why this constitutes a MPD bug - MPD is just doing what the client tells it to do.

Answer 4 · 2024-05-10T15:40:39.000Z

This loop is caused by repeated commands received from your client. You have not explained why this constitutes a MPD bug - MPD is just doing what the client tells it to do.

With a NFSv3 server i can switch albums and everything works fine. If i switch to NFSv4 the second album get in this loop. Thought indeed about a configuration error, but that does not explain why NFSv3 works.

Answer 5 · 2024-05-10T15:45:01.000Z

I have no idea, but nothing in your bug report describes a MPD problem. You wrote that MPD does play the second album, and the only problem you described is with Cantata. You better report this problem to Cantata. Maybe there is an underlying problem in MPD, but I can't know that because your bug report says nothing about it. Until you have data that backs up your claim that the problem is MPD, I have to close your bug report.