Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

When an NFS mount disconnects, music is still not available after reconnect #690

Open
beniamino38 opened this issue Feb 11, 2019 · 2 comments

Comments

@beniamino38
Copy link

commented Feb 11, 2019

If music is stored on a NFS share, and the share fails to mount when forked-daapd starts up, the music is not available even after the NFS share is remounted. A full rescan is required for the music to be available again.

Steps to reproduce:

pi-sitting is a raspberry pi sharing a music library over NFS.
pi-dining is a raspberry pi mounting the NFS shared library from pi-sitting as /remote/Bens-Music, and using this as the root directory for forked-daapd

# turn off the NFS server
ben@pi-sitting:~ $ sudo service nfs-kernel-server stop

# restart forked-daapd by restarting the machine
ben@pi-dining:~ $ sudo reboot

# pi-dining:/var/log/syslog
...
Feb 11 22:20:04 pi-dining systemd[1]: remote.mount: Mounting timed out. Stopping.
Feb 11 22:20:04 pi-dining systemd[1]: remote.mount: Mount process exited, code=killed status=15
Feb 11 22:20:04 pi-dining systemd[1]: Failed to mount /remote.
Feb 11 22:20:04 pi-dining systemd[1]: remote.mount: Unit entered failed state.
Feb 11 22:20:04 pi-dining forked-daapd[408]: [  LOG]     scan: Skipping library directory /remote/Bens-Music, could not dereference: No such device
...

# Restart the NFS server. We expect music to be available again.
ben@pi-sitting:~ $ sudo service nfs-kernel-server start

# Navigate to http://pi-dining:3689
# This triggers /remote to be remounted, and forked-daapd comes back to life...

# pi-dining:/var/log/syslog
...
Feb 11 22:21:23 pi-dining systemd[1]: remote.automount: Got automount request for /remote, triggered by 723 (httpd)
Feb 11 22:21:23 pi-dining systemd[1]: Mounting /remote...
Feb 11 22:21:23 pi-dining forked-daapd[408]: [  LOG]     scan: Bulk library scan completed in 94 sec
Feb 11 22:21:24 pi-dining systemd[1]: Mounted /remote.
Feb 11 22:21:24 pi-dining forked-daapd[408]: [  LOG]  spotify: Login to Spotify succeeded (libspotify)
Feb 11 22:21:25 pi-dining forked-daapd[408]: [  LOG]  spotify: Connection to Spotify (re)established (libspotify)
Feb 11 22:21:28 pi-dining forked-daapd[408]: [  LOG]  spotify: Scanned 10 of 17 saved albums
Feb 11 22:21:31 pi-dining forked-daapd[408]: [  LOG]  spotify: Scanned 17 of 17 saved albums
Feb 11 22:21:32 pi-dining forked-daapd[408]: [  LOG]  spotify: Scanned 1 of 1 saved playlists
Feb 11 22:21:32 pi-dining forked-daapd[408]: [  LOG]  spotify: Spotify scan completed in 7 sec
Feb 11 22:21:36 pi-dining forked-daapd[408]: [  LOG]      lib: Library init scan completed in 108 sec (2 changes)
Feb 11 22:21:46 pi-dining forked-daapd[408]: [  LOG]    cache: Beginning DAAP cache update
Feb 11 22:21:47 pi-dining forked-daapd[408]: [  LOG]    cache: DAAP cache updated
...

# Now, it looks like everything is working, but no songs from /remote/Bens-Music are available in the web interface (although Spotify songs are available)

# Try restarting forked-daapd to get the songs back
ben@pi-dining:~ $ sudo service forked-daapd restart

# pi-dining:/var/log/syslog
...
Feb 11 22:26:46 pi-dining forked-daapd[889]: [  LOG]       db: Now vacuuming database, this may take some time...
Feb 11 22:26:59 pi-dining forked-daapd[889]: [  LOG]       db: Database OK with 349 active files and 9 active playlists
Feb 11 22:27:03 pi-dining forked-daapd[889]: [  LOG]     scan: Scanned 200 files...
...
Feb 11 22:30:03 pi-dining forked-daapd[889]: [  LOG]     scan: Scanned 10600 files...
Feb 11 22:30:12 pi-dining forked-daapd[889]: [  LOG]     scan: Unchanged playlist found, not processing '/remote/Bens-Music/Radio/BBC Radio 3.m3u'
...
Feb 11 22:30:12 pi-dining forked-daapd[889]: [  LOG]     scan: Bulk library scan completed in 193 sec
Feb 11 22:30:13 pi-dining forked-daapd[889]: [  LOG]  spotify: Login to Spotify succeeded (libspotify)
Feb 11 22:30:14 pi-dining forked-daapd[889]: [  LOG]  spotify: Connection to Spotify (re)established (libspotify)
Feb 11 22:30:18 pi-dining forked-daapd[889]: [  LOG]  spotify: Scanned 10 of 17 saved albums
Feb 11 22:30:22 pi-dining forked-daapd[889]: [  LOG]  spotify: Scanned 17 of 17 saved albums
Feb 11 22:30:24 pi-dining forked-daapd[889]: [  LOG]  spotify: Scanned 1 of 1 saved playlists
Feb 11 22:30:24 pi-dining forked-daapd[889]: [  LOG]  spotify: Spotify scan completed in 10 sec
Feb 11 22:30:28 pi-dining forked-daapd[889]: [  LOG]      lib: Library init scan completed in 209 sec (0 changes)

# Again, it looks like everything is working, but no songs from /remote/Bens-Music are available in the web interface.

# Try triggering an init-rescan
ben@pi-dining:~ $ touch /forked-daapd/trigger.init-rescan 

# pi-dining:/var/log/syslog
...
Feb 11 22:35:53 pi-dining forked-daapd[889]: [  LOG]      lib: Library rescan triggered
Feb 11 22:35:53 pi-dining forked-daapd[889]: [  LOG]     scan: Startup rescan triggered
Feb 11 22:36:01 pi-dining forked-daapd[889]: [  LOG]     scan: Scanned 200 files...
...
Feb 11 22:41:09 pi-dining forked-daapd[889]: [  LOG]  spotify: Spotify scan completed in 9 sec
Feb 11 22:41:13 pi-dining forked-daapd[889]: [  LOG]      lib: Library rescan completed in 320 sec (0 changes)
...

# Again, it looks like everything is working, but no songs from /remote/Bens-Music are available in the web interface.```

@ejurgensen

This comment has been minimized.

Copy link
Owner

commented Feb 12, 2019

Thanks for the thorough report. I had a look at the code, and I can see that the disable happens here:
https://github.com/ejurgensen/forked-daapd/blob/master/src/library/filescanner.c#L1069

It is less clear how/where the directories/files are supposed to be enabled again. I'm not sure what events inotify gives when mounting a nfs volume. Can you set log level to debug and then try to remount? Then look in the log for this log event (hope it is there...):
https://github.com/ejurgensen/forked-daapd/blob/master/src/library/filescanner.c#L1067

I know it is a bit much to ask, but if you are able to trace what happens in the code during remount it is a tremendous help.

@beniamino38

This comment has been minimized.

Copy link
Author

commented Feb 14, 2019

This log is from starting up forked-daapd when the music is on an NFS drive that can't be mounted because the NFS server is down. (This is an ubuntu machine, not the raspberry pi from the previous log). I'm not sure the disable is happening -- perhaps because forked-daapd can't tell that the drive is missing. If I ls /remote, then it just fails to return for a long time, rather than producing an error. I imagine something similar happens when forked-daapd tries to access the drive.

forked.daapd.cropped.log

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
2 participants
You can’t perform that action at this time.