2017-03-28 06:18 CEST

View Issue Details Jump to Notes ]
IDProjectCategoryView StatusLast Update
0004081MPDMPDpublic2017-02-01 21:47
Reportersellsky 
Assigned Tocirrus 
PrioritynormalSeverityminorReproducibilityalways
StatusresolvedResolutionfixed 
Platformx86_64OSGentoo LinuxOS Versionrolling
Product Versiongit 
Target VersionFixed in Version0.20 
Summary0004081: MPD still stops playing after been paused for a while if music_directory use nfs://
DescriptionI can reproduce issue that marked resolved in http://bugs.musicpd.org/view.php?id=4074


I set music_directory to, say, “nfs://192.168.1.2/srv/music”. MPD starts playing a more or less long track, I pause it and wait for a while, a half an hour or so.

Then I resume play, MPD changes its state to playing, but does not play at all. It remains fully accessible, responds to pause and play commands as well, changing status accordingly, but it just doesn't play anything.

In status response, mpd_time and mpd_elapsed do not advance.

If I “mount -t nfs 192.168.1.2:/srv/music /var/lib/mpd/music” and set music_directory to "/var/lib/mpd/music", then I can't reproduce this.


I checked that cloned source has reconnect code from recent commits. "mpd --version" say "Music Player Daemon 0.19~git (v0.18.13-1384-g60589fc)".
TagsNo tags attached.
Attached Files
  • ? file icon log (5,305 bytes) 2014-09-03 11:07 -
    Sep 03 11:37 : state_file: Loading state file /var/lib/mpd/state
    Sep 03 11:37 : playlist: play 4:"rock/Poe - 2000 Haunted/05.Walk the Walk.flac"
    Sep 03 11:37 : replay_gain: replay gain mode has changed -1->0
    Sep 03 11:37 : replay_gain: scale=1.000000
    Sep 03 11:37 : replay_gain: replay gain mode has changed -1->0
    Sep 03 11:37 : replay_gain: scale=1.000000
    Sep 03 11:37 : playlist: queue song 5:"rock/Poe - 2000 Haunted/06.Terrified Heart.flac"
    Sep 03 11:37 : decoder_thread: probing plugin flac
    Sep 03 11:37 : decoder: audio_format=44100:16:2, seekable=true
    Sep 03 11:38 : client: [0] opened from 127.0.0.1:47053
    Sep 03 11:38 : client: [0] process command "password password"
    Sep 03 11:38 : client: [0] command returned 0
    Sep 03 11:38 : client: [0] process command "play"
    Sep 03 11:38 : alsa_output: opened mpdvol type=SOFTVOL
    Sep 03 11:38 : alsa_output: format=S32_LE (Signed 32 bit Little Endian)
    Sep 03 11:38 : alsa_output: buffer: size=2048..16384 time=21333..170667
    Sep 03 11:38 : alsa_output: period: size=1024..1024 time=10666..10667
    Sep 03 11:38 : alsa_output: default period_time = buffer_time/4 = 170666/4 = 42666
    Sep 03 11:38 : alsa_output: buffer_size=16384 period_size=1024
    Sep 03 11:38 : libsamplerate: setting samplerate conversion ratio to 2.18
    Sep 03 11:38 : output: opened plugin=alsa name="Xonar XDG" audio_format=96000:32:2
    Sep 03 11:38 : output: converting from 44100:16:2
    Sep 03 11:38 : replay_gain: scale=0.397192
    Sep 03 11:38 : client: [0] command returned 0
    Sep 03 11:38 : client: [0] closed
    Sep 03 11:38 : client: [1] opened from 127.0.0.1:47055
    Sep 03 11:38 : client: [1] process command "password password"
    Sep 03 11:38 : client: [1] command returned 0
    Sep 03 11:38 : client: [1] process command "pause"
    Sep 03 11:38 : client: [1] command returned 0
    Sep 03 11:38 : output: closed plugin=alsa name="Xonar XDG"
    Sep 03 11:38 : client: [1] closed
    Sep 03 11:40 : state_file: Saving state file /var/lib/mpd/state
    Sep 03 12:08 : client: [2] opened from 127.0.0.1:47243
    Sep 03 12:08 : client: [2] process command "password password"
    Sep 03 12:08 : client: [2] command returned 0
    Sep 03 12:08 : client: [2] process command "play"
    Sep 03 12:08 : alsa_output: opened mpdvol type=SOFTVOL
    Sep 03 12:08 : alsa_output: format=S32_LE (Signed 32 bit Little Endian)
    Sep 03 12:08 : alsa_output: buffer: size=2048..16384 time=21333..170667
    Sep 03 12:08 : alsa_output: period: size=1024..1024 time=10666..10667
    Sep 03 12:08 : alsa_output: default period_time = buffer_time/4 = 170666/4 = 42666
    Sep 03 12:08 : alsa_output: buffer_size=16384 period_size=1024
    Sep 03 12:08 : libsamplerate: setting samplerate conversion ratio to 2.18
    Sep 03 12:08 : output: opened plugin=alsa name="Xonar XDG" audio_format=96000:32:2
    Sep 03 12:08 : output: converting from 44100:16:2
    Sep 03 12:08 : client: [2] command returned 0
    Sep 03 12:08 : client: [2] closed
    Sep 03 12:08 : replay_gain: scale=1.000000
    Sep 03 12:09 : client: [3] opened from 127.0.0.1:47245
    Sep 03 12:09 : client: [3] process command "password password"
    Sep 03 12:09 : client: [3] command returned 0
    Sep 03 12:09 : client: [3] process command "status"
    Sep 03 12:09 : client: [3] command returned 0
    Sep 03 12:09 : client: [3] closed
    Sep 03 12:09 : client: [4] opened from 127.0.0.1:47246
    Sep 03 12:09 : client: [4] process command "password password"
    Sep 03 12:09 : client: [4] command returned 0
    Sep 03 12:09 : client: [4] process command "pause"
    Sep 03 12:09 : client: [4] command returned 0
    Sep 03 12:09 : output: closed plugin=alsa name="Xonar XDG"
    Sep 03 12:09 : client: [4] closed
    Sep 03 12:09 : client: [5] opened from 127.0.0.1:47247
    Sep 03 12:09 : client: [5] process command "password password"
    Sep 03 12:09 : client: [5] command returned 0
    Sep 03 12:09 : client: [5] process command "status"
    Sep 03 12:09 : client: [5] command returned 0
    Sep 03 12:09 : client: [5] closed
    Sep 03 12:09 : client: [6] opened from 127.0.0.1:47248
    Sep 03 12:09 : client: [6] process command "password password"
    Sep 03 12:09 : client: [6] command returned 0
    Sep 03 12:09 : client: [6] process command "play"
    Sep 03 12:09 : alsa_output: opened mpdvol type=SOFTVOL
    Sep 03 12:09 : alsa_output: format=S32_LE (Signed 32 bit Little Endian)
    Sep 03 12:09 : alsa_output: buffer: size=2048..16384 time=21333..170667
    Sep 03 12:09 : alsa_output: period: size=1024..1024 time=10666..10667
    Sep 03 12:09 : alsa_output: default period_time = buffer_time/4 = 170666/4 = 42666
    Sep 03 12:09 : alsa_output: buffer_size=16384 period_size=1024
    Sep 03 12:09 : libsamplerate: setting samplerate conversion ratio to 2.18
    Sep 03 12:09 : output: opened plugin=alsa name="Xonar XDG" audio_format=96000:32:2
    Sep 03 12:09 : output: converting from 44100:16:2
    Sep 03 12:09 : client: [6] command returned 0
    Sep 03 12:09 : client: [6] closed
    Sep 03 12:09 : client: [7] opened from 127.0.0.1:47249
    Sep 03 12:09 : client: [7] process command "password password"
    Sep 03 12:09 : client: [7] command returned 0
    Sep 03 12:09 : client: [7] process command "status"
    Sep 03 12:09 : client: [7] command returned 0
    Sep 03 12:09 : client: [7] closed
    Sep 03 12:09 : state_file: Saving state file /var/lib/mpd/state
    Sep 03 12:09 : player: played "rock/Poe - 2000 Haunted/05.Walk the Walk.flac"
    Sep 03 12:09 : output: closed plugin=alsa name="Xonar XDG"
    Sep 03 12:09 : listen: listen_global_finish called
    
    ? file icon log (5,305 bytes) 2014-09-03 11:07 +
  • ? file icon mpd.conf (786 bytes) 2014-09-03 11:07
  • log file icon console.log (2,649 bytes) 2014-09-03 11:11

-Relationships
+Relationships

-Notes

~0008734

sellsky (reporter)

I also attach console log. There are some dates, I issued latest date command right after MPD stopped playing.

~0008745

sellsky (reporter)

I don't quite understand how MPD works, so I could miss something important from my issue description. I can apply a patch and run some debug code, if needeed, I guess.

~0008747

cirrus (administrator)

Paste the output of "mpd --version"

~0008749

sellsky (reporter)

$ mpd --version
Music Player Daemon 0.19~git (v0.18.13-1384-g60589fc)

Copyright (C) 2003-2007 Warren Dukes <warren.dukes@gmail.com>
Copyright (C) 2008-2014 Max Kellermann <max@duempel.org>
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

Storage plugins:
 local nfs

Decoders plugins:
 [mad] mp3 mp2
 [vorbis] ogg oga
 [oggflac] ogg oga
 [flac] flac
 [dsdiff] dff
 [dsf] dsf
 [modplug] 669 amf ams dbm dfm dsm far it med mdl mod mtm mt2 okt s3m stm ult umx xm
 [ffmpeg] 16sv 3g2 3gp 4xm 8svx aa3 aac ac3 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 psp pva qcp qt r3d ra ram rl2 rm rmvb roq rpl rvc shn smk snd sol son spx str swf 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
 [pcm]

Output plugins:
 shout null fifo alsa httpd

Encoder plugins:
 null vorbis flac

Archive plugins:
 [bz2] bz2

Input plugins:
 file alsa archive curl ffmpeg nfs

Playlist plugins:
 extm3u m3u pls xspf asx rss cue cue

Protocols:
 file:// http:// https:// gopher:// rtp:// rtsp:// rtmp:// rtmpt:// rtmps:// nfs:// alsa://

~0009143

cirrus (administrator)

Quite a few bugs regarding NFS have been fixed in 0.19.5. This bug may be fixed, too, but I'm not sure. Please check if this still occurs.

~0009174

cirrus (administrator)

Reopen if it still occurs.

~0009789

sellsky (reporter)

Unfortunately, the bug is still here. Logs and overall behavior are the same as in 2014.

I attached current version, config and NFS kernel settings for both client and server, can there be the problem? I don't know what else can I report.

MPD and NFS client:
---
$ mpd --version
Music Player Daemon 0.19.12

Copyright (C) 2003-2007 Warren Dukes <warren.dukes@gmail.com>
Copyright (C) 2008-2014 Max Kellermann <max@duempel.org>
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

Storage plugins:
 local nfs

Decoders plugins:
 [mad] mp3 mp2
 [vorbis] ogg oga
 [oggflac] ogg oga
 [flac] flac
 [dsdiff] dff
 [dsf] dsf
 [modplug] 669 amf ams dbm dfm dsm far it med mdl mod mtm mt2 okt s3m stm ult umx xm
 [ffmpeg] 16sv 3g2 3gp 4xm 8svx aa3 aac ac3 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 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
 [pcm]

Output plugins:
 shout null fifo alsa httpd

Encoder plugins:
 null vorbis flac

Archive plugins:
 [bz2] bz2

Input plugins:
 file alsa archive curl ffmpeg nfs

Playlist plugins:
 extm3u m3u pls cue embcue

Protocols:
 file:// http:// https:// gopher:// rtp:// rtsp:// rtmp:// rtmpt:// rtmps:// nfs:// alsa://

sk@rb ~ $ egrep -v '^#|^$' /etc/mpd.conf | sed -re '/^password|^\s*host/ s/".+@/"***@/'
music_directory "nfs://192.168.1.24/srv/music"
playlist_directory "/var/lib/mpd/playlists"
database {
       plugin "proxy"
       host "***@192.168.1.24"
       port "7670"
}
log_file "/var/log/mpd/log"
pid_file "/var/lib/mpd/pid"
state_file "/var/lib/mpd/state"
user "sk"
group "audio"
bind_to_address "any"
log_level "default"
metadata_to_use "artist,album,title,track,name,date,composer,performer,disc"
auto_update "yes"
follow_inside_symlinks "yes"
password "***@read,add,control,admin"
audio_output {
        type "alsa"
        name "Xonar XDG"
        device "dmixer"
        mixer_type "software"
}
samplerate_converter "Best Sinc Interpolator"
replaygain "auto"
connection_timeout "60"
max_playlist_length "65536"
filesystem_charset "UTF-8"
id3v1_encoding "cp1251"

sk@rb ~ $ zgrep -i nfs /proc/config.gz
CONFIG_KERNFS=y
CONFIG_NFS_FS=m
CONFIG_NFS_V2=m
CONFIG_NFS_V3=m
CONFIG_NFS_V3_ACL=y
CONFIG_NFS_V4=m
# CONFIG_NFS_SWAP is not set
CONFIG_NFS_V4_1=y
CONFIG_NFS_V4_2=y
CONFIG_PNFS_FILE_LAYOUT=m
CONFIG_PNFS_FLEXFILE_LAYOUT=m
CONFIG_NFS_V4_1_IMPLEMENTATION_ID_DOMAIN="kernel.org"
# CONFIG_NFS_V4_1_MIGRATION is not set
CONFIG_NFS_V4_SECURITY_LABEL=y
CONFIG_NFS_FSCACHE=y
# CONFIG_NFS_USE_LEGACY_DNS is not set
CONFIG_NFS_USE_KERNEL_DNS=y
CONFIG_NFSD=m
CONFIG_NFSD_V2_ACL=y
CONFIG_NFSD_V3=y
CONFIG_NFSD_V3_ACL=y
CONFIG_NFSD_V4=y
# CONFIG_NFSD_PNFS is not set
# CONFIG_NFSD_V4_SECURITY_LABEL is not set
CONFIG_NFS_ACL_SUPPORT=m
CONFIG_NFS_COMMON=y
---

NFS server:
---
sk@ad ~ $ zgrep -i nfs /proc/config.gz
CONFIG_KERNFS=y
CONFIG_NFS_FS=m
CONFIG_NFS_V2=m
CONFIG_NFS_V3=m
CONFIG_NFS_V3_ACL=y
CONFIG_NFS_V4=m
# CONFIG_NFS_SWAP is not set
CONFIG_NFS_V4_1=y
CONFIG_NFS_V4_2=y
CONFIG_PNFS_FILE_LAYOUT=m
CONFIG_PNFS_FLEXFILE_LAYOUT=m
CONFIG_NFS_V4_1_IMPLEMENTATION_ID_DOMAIN="kernel.org"
# CONFIG_NFS_V4_1_MIGRATION is not set
CONFIG_NFS_FSCACHE=y
# CONFIG_NFS_USE_LEGACY_DNS is not set
CONFIG_NFS_USE_KERNEL_DNS=y
CONFIG_NFS_DEBUG=y
CONFIG_NFSD=m
CONFIG_NFSD_V2_ACL=y
CONFIG_NFSD_V3=y
CONFIG_NFSD_V3_ACL=y
CONFIG_NFSD_V4=y
# CONFIG_NFSD_PNFS is not set
CONFIG_NFS_ACL_SUPPORT=m
CONFIG_NFS_COMMON=y
---

~0010301

cirrus (administrator)

05eac20ffe5af325ac7d4019e72d3ac0b69d494a

Sorry for the looong delay, but this was a pretty complicated bug, with a very simple solution. I hope I fixed it really this time.
+Notes

-Issue History
Date Modified Username Field Change
2014-09-03 11:07 sellsky New Issue
2014-09-03 11:07 sellsky File Added: log
2014-09-03 11:07 sellsky File Added: mpd.conf
2014-09-03 11:11 sellsky Note Added: 0008734
2014-09-03 11:11 sellsky File Added: console.log
2014-09-03 20:54 sellsky Note Added: 0008745
2014-09-04 14:37 cirrus Note Added: 0008747
2014-09-04 16:17 sellsky Note Added: 0008749
2014-11-25 17:09 cirrus Note Added: 0009143
2014-12-08 14:57 cirrus Note Added: 0009174
2014-12-08 14:57 cirrus Status new => resolved
2014-12-08 14:57 cirrus Fixed in Version => 0.19
2014-12-08 14:57 cirrus Resolution open => fixed
2014-12-08 14:57 cirrus Assigned To => cirrus
2016-02-15 21:19 sellsky Note Added: 0009789
2016-02-15 21:19 sellsky Status resolved => feedback
2016-02-15 21:19 sellsky Resolution fixed => reopened
2017-02-01 21:47 cirrus Status feedback => resolved
2017-02-01 21:47 cirrus Resolution reopened => fixed
2017-02-01 21:47 cirrus Fixed in Version 0.19 => 0.20
2017-02-01 21:47 cirrus Note Added: 0010301
+Issue History