[Bug]: Jukebox playback graceful shutdown

korzhyc commented 2 weeks ago

I confirm that:

[X] I have searched the existing open AND closed issues to see if an issue already exists for the bug I've encountered
[X] I'm using the latest version (your issue may have been fixed already)

Version

0.51.1-SNAPSHOT (6dcfe4d4)

Current Behavior

When I stop Navidrome service while jukebox playback is active, this leads to the following possible outcomes:

Variant 1: mpv process got roughly killed. Variant 2 (less frequent): mpv got restarted and is left in free flight (until the track ends).

Expected Behavior

A proper handling of the shutdown command.

Steps To Reproduce

No response

Environment

- OS: Windows Server 2022, mpv-0.37.0-x86_64-v3
- Client: DSub 5.5.3, Ultrasonic 4.8.0

How Navidrome is installed?

Binary (from downloads page)

Configuration

# shawl add --name "Navidrome" --no-restart --stop-timeout=5000 --log-rotate bytes=524288 --log-cmd-as "Navidrome" --log-dir "c:\Srv\Navidrome\data" --cwd "C:\Srv\Navidrome" --env "MPV_HOME=C:\Srv\Navidrome\jukebox" -- "navidrome.exe"

# navidrome.toml:
LogLevel = 'debug'
DataFolder = '.\data'
MusicFolder = 'F:\Music'
Jukebox.Enabled = true
Jukebox.Devices = [
  ['realtek_spdif', 'wasapi/{eebf0aab-21a9-4d68-8759-22f533c960e7}']
]
MPVPath = 'c:\bin\mpv\mpv.com'

Relevant log output

---------- Variant 1 ----------
...
time="2024-04-21T18:37:09+03:00" level=debug msg="Unpausing track" [CUT]
time="2024-04-21T18:37:34+03:00" level=info msg="Received termination signal" signal=interrupt
time="2024-04-21T18:37:34+03:00" level=info msg="Stopping HTTP server"
time="2024-04-21T18:37:34+03:00" level=debug msg="Scheduler: stop"
time="2024-04-21T18:37:34+03:00" level=info msg="Closing Database"
time="2024-04-21T18:37:34+03:00" level=info msg="Navidrome stopped, bye."
[EOF]

mpv.log:
...
[   0.114][v][cplayer] audio ready
[   0.114][v][cplayer] starting audio playback
[   0.114][d][ao/wasapi] Thread Resume
[   0.114][d][ao/wasapi] Thread Reset
[   0.114][v][cplayer] playback restart complete @ 0.000018, audio=playing, video=eof
[   1.113][v][ao/wasapi] OnPropertyValueChanged triggered on device {0.0.0.00000000}.{eebf0aab-21a9-4d68-8759-22f533c960e7}
[   1.113][v][ao/wasapi] Changed property: {9855c4cd-df8c-449c-a181-8191b68bd06c},0
[EOF]

---------- Variant 2 ----------
...
time="2024-04-21T18:50:35+03:00" level=info msg="Received termination signal" signal=interrupt
time="2024-04-21T18:50:35+03:00" level=info msg="Stopping HTTP server"
time="2024-04-21T18:50:35+03:00" level=debug msg="Scheduler: stop"
time="2024-04-21T18:50:35+03:00" level=info msg="Hitting end-of-stream, signalling on channel"
time="2024-04-21T18:50:35+03:00" level=debug msg="Track switching detected"
time="2024-04-21T18:50:35+03:00" level=debug msg="Closing resources" [CUT]
time="2024-04-21T18:50:35+03:00" level=debug msg="Switching to next song" queue="#Items: 21, idx: 16, [CUT]"
time="2024-04-21T18:50:35+03:00" level=debug msg="Loading track" [CUT]
time="2024-04-21T18:50:35+03:00" level=debug msg="Executing mpv command" [CUT]
time="2024-04-21T18:50:35+03:00" level=debug msg="Socket found" retries=1 waitTime=121.5ms
time="2024-04-21T18:50:35+03:00" level=debug msg="Unpausing track" [CUT]
time="2024-04-21T18:50:38+03:00" level=info msg="Closing Database"
time="2024-04-21T18:50:38+03:00" level=info msg="Navidrome stopped, bye."
[EOF]

Anything else?

No response

Code of Conduct

[X] I agree to follow Navidrome's Code of Conduct

deluan commented 2 weeks ago

Thanks for opening this. As I mentioned before, I think this is caused by the improper handling of context cancellation.

Dev notes:

When Navidrome starts, it creates a context.Context and passes it to long lived subsystems (server, scanner, cron, playback, ...).

When the main process receives a termination signal, it uses this context to stop all subsystems, which should allow them to gracefully close all resources in use. Seems that the core.Playback subsystem (our Jukebox implementation), is not handling this correctly.

@ms140569 Any thoughts?

ms140569 commented 2 weeks ago

@deluan you are totally right. We need to send Clear() to all devices in core/playback/playbackserver.go right between line #57 and #58.

I‘m away from keyboard right now, but can do this starting on Friday.

ms140569 commented 1 week ago

This should do the trick:

https://github.com/navidrome/navidrome/pull/2995

HTH, Matthias

ms140569 commented 1 week ago

OK, the PR hangs in the checks. @deluan could you take a look here, than it seems to be a infrastructure problem.

deluan commented 1 week ago

Hey @korzhyc, can you try the build from the PR and let us know if it solves your issues?

korzhyc commented 1 week ago

...actually no.

Regarding variant 1 (mpv process kill), I don’t think we should pay attention to this, because... the same thing happens on track switching.

                 Version: 0.52.0-SNAPSHOT (9e07e35f)
...
time="2024-05-08T22:52:56+03:00" level=debug msg="Checking if track is playing" track="Name: F:\\Music\\-x-dub-chill\\Pensees - 2017 - Sleepaway\\13 - Dereal (Bonus Track).mp3, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-bebfcf71-27a0-4c24-b5d9-e82c5f478973.socket"
time="2024-05-08T23:10:28+03:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=WIN-6H9506BP7VG/jSq7wdBI2k-000018 status=OK
time="2024-05-08T23:10:28+03:00" level=debug msg="HTTP: GET http://10.0.2.11:4533/rest/jukeboxControl.view?action=status&u=guest&c=Ultrasonic&f=json&v=1.16.0&t=[REDACTED]&s=[REDACTED]" elapsedTime=1.6ms httpStatus=200 remoteAddr="10.0.2.3:55591" requestId=WIN-6H9506BP7VG/jSq7wdBI2k-000018 responseSize=212 userAgent=okhttp/4.11.0
time="2024-05-08T23:10:31+03:00" level=info msg="Shutting down audio devices"
time="2024-05-08T23:10:31+03:00" level=info msg="Stopping HTTP server"
time="2024-05-08T23:10:31+03:00" level=debug msg="Scheduler: stop"
time="2024-05-08T23:10:31+03:00" level=debug msg="Processing Clear action" device="Name: realtek_spdif, Gain: 1.0000, Loaded track: Name: F:\\Music\\-x-dub-chill\\Pensees - 2017 - Sleepaway\\13 - Dereal (Bonus Track).mp3, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-e02d95f9-e3bf-4407-8fe5-5cafadb15ba0.socket"
time="2024-05-08T23:10:31+03:00" level=debug msg="Pausing track" track="Name: F:\\Music\\-x-dub-chill\\Pensees - 2017 - Sleepaway\\13 - Dereal (Bonus Track).mp3, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-e02d95f9-e3bf-4407-8fe5-5cafadb15ba0.socket"
time="2024-05-08T23:10:31+03:00" level=info msg="Hitting end-of-stream, signalling on channel"
time="2024-05-08T23:10:31+03:00" level=debug msg="Track switching detected"
time="2024-05-08T23:10:31+03:00" level=debug msg="Closing resources" track="Name: F:\\Music\\-x-dub-chill\\Pensees - 2017 - Sleepaway\\13 - Dereal (Bonus Track).mp3, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-e02d95f9-e3bf-4407-8fe5-5cafadb15ba0.socket"
time="2024-05-08T23:10:31+03:00" level=debug msg="There is no song left in the playlist. Finish."
[EOF]

mpv.log:
[   0.308][v][cplayer] Set property: pause=false -> 1
[   1.066][v][ao/wasapi] OnPropertyValueChanged triggered on device {0.0.0.00000000}.{eebf0aab-21a9-4d68-8759-22f533c960e7}
[   1.066][v][ao/wasapi] Changed property: {9855c4cd-df8c-449c-a181-8191b68bd06c},0
[EOF]

As for the second, I caught it again...

time="2024-05-08T22:52:56+03:00" level=debug msg="Checking if track is playing" track="Name: F:\\Music\\-x-dub-chill\\Pensees - 2017 - Sleepaway\\13 - Dereal (Bonus Track).mp3, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-bebfcf71-27a0-4c24-b5d9-e82c5f478973.socket"
time="2024-05-08T22:52:56+03:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=WIN-6H9506BP7VG/0E5BLxISij-000064 status=OK
time="2024-05-08T22:52:56+03:00" level=debug msg="HTTP: GET http://10.0.2.11:4533/rest/jukeboxControl.view?action=status&u=guest&c=Ultrasonic&f=json&v=1.16.0&t=[REDACTED]&s=[REDACTED]" elapsedTime="518.9Вµs" httpStatus=200 remoteAddr="10.0.2.3:55484" requestId=WIN-6H9506BP7VG/0E5BLxISij-000064 responseSize=214 userAgent=okhttp/4.11.0
time="2024-05-08T22:52:58+03:00" level=info msg="Shutting down audio devices"
time="2024-05-08T22:52:58+03:00" level=debug msg="Processing Clear action" device="Name: realtek_spdif, Gain: 1.0000, Loaded track: Name: F:\\Music\\-x-dub-chill\\Pensees - 2017 - Sleepaway\\13 - Dereal (Bonus Track).mp3, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-bebfcf71-27a0-4c24-b5d9-e82c5f478973.socket"
time="2024-05-08T22:52:58+03:00" level=info msg="Stopping HTTP server"
time="2024-05-08T22:52:58+03:00" level=debug msg="Pausing track" track="Name: F:\\Music\\-x-dub-chill\\Pensees - 2017 - Sleepaway\\13 - Dereal (Bonus Track).mp3, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-bebfcf71-27a0-4c24-b5d9-e82c5f478973.socket"
time="2024-05-08T22:52:58+03:00" level=debug msg="Scheduler: stop"
time="2024-05-08T22:52:58+03:00" level=info msg="Hitting end-of-stream, signalling on channel"
time="2024-05-08T22:52:58+03:00" level=debug msg="Track switching detected"
time="2024-05-08T22:52:58+03:00" level=debug msg="Closing resources" track="Name: F:\\Music\\-x-dub-chill\\Pensees - 2017 - Sleepaway\\13 - Dereal (Bonus Track).mp3, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-bebfcf71-27a0-4c24-b5d9-e82c5f478973.socket"
time="2024-05-08T22:52:58+03:00" level=debug msg="Switching to next song" queue="#Items: 2, idx: 1, files: 0:F:\\Music\\-x-dub-chill\\Pensees - 2017 - Sleepaway\\13 - Dereal (Bonus Track).mp3 1:F:\\Music\\-x-dub-chill\\Pensees - 2017 - Sleepaway\\08 - Eclipse.mp3 "
time="2024-05-08T22:52:58+03:00" level=debug msg="Loading track" mediaType=audio/mpeg trackPath="F:\\Music\\-x-dub-chill\\Pensees - 2017 - Sleepaway\\08 - Eclipse.mp3"
time="2024-05-08T22:52:58+03:00" level=debug msg="Executing mpv command" cmd="[c:\\bin\\mpv\\mpv.com --audio-device=wasapi/{eebf0aab-21a9-4d68-8759-22f533c960e7} --no-audio-display --pause F:\\Music\\-x-dub-chill\\Pensees - 2017 - Sleepaway\\08 - Eclipse.mp3 --input-ipc-server=\\\\.\\pipe\\mpvsocket\\mpv-ctrl-3b139590-999a-4c2b-a8b3-675cb10cc194.socket]"
time="2024-05-08T22:52:59+03:00" level=debug msg="Socket found" retries=1 waitTime=108.8ms
time="2024-05-08T22:52:59+03:00" level=debug msg="Unpausing track" track="Name: F:\\Music\\-x-dub-chill\\Pensees - 2017 - Sleepaway\\08 - Eclipse.mp3, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-3b139590-999a-4c2b-a8b3-675cb10cc194.socket"
[EOF]

deluan commented 1 week ago

...actually no.

:(

@ms140569 I think a proper solution is to use the context passed to PlaybackServerRun() to cancel any external process, by passing that context to the exec.CommandContext() call.

deluan commented 1 week ago

@korzhyc I put another possible solution in place in PR #3008. Please let me know if it solves the issue.

korzhyc commented 1 week ago

Also, about mpv process kill... I have a thought:

If we had waited for the process to complete correctly, then perhaps there would have been no problems with wasapi exclusive output (there is a workaround for the issue on the mpv side, around here).

Graceful mpv shutdown, for example:

[   0.101][v][cplayer] Set property: pause=false -> 1
[ 355.442][v][lavf] EOF reached.
[ 356.432][v][af] filter input EOF
[ 356.432][v][af] filter output EOF
[ 356.432][v][cplayer] audio filter EOF
[ 356.432][v][cplayer] audio draining
[ 356.432][v][cplayer] audio EOF reached
[ 356.432][v][cplayer] EOF code: 1  
[ 356.432][d][ad] Uninit decoder.
[ 356.432][d][cplayer] Terminating demuxers...
[ 356.432][d][cplayer] Done terminating demuxers.
[ 356.432][v][cplayer] finished playback, success (reason 0)
[ 356.432][i][cplayer] Exiting... (End of file)
[ 356.432][d][ipc_1] Exiting...
[ 356.433][v][cplayer] draining left over audio
[ 356.652][d][ao/wasapi] Uninit wasapi
[ 356.652][d][ao/wasapi] Thread Reset
[ 356.652][d][ao/wasapi] Thread Reset
[ 356.652][d][ao/wasapi] Thread shutdown
[ 356.653][d][ao/wasapi] Thread uninit done
[ 356.653][d][ao/wasapi] Thread return
[ 356.653][d][ao/wasapi] Uninit wasapi done
[EOF]

deluan commented 1 week ago

@korzhyc Binaries and Docker image are available for #3008. Please give feedback whenever you can.

korzhyc commented 1 week ago

Seems okay.

The order sometimes differs:

time="2024-05-09T02:22:01+03:00" level=debug msg="Stopping trackSwitcher goroutine" device="wasapi/{eebf0aab-21a9-4d68-8759-22f533c960e7}"
time="2024-05-09T02:22:01+03:00" level=info msg="Stopping HTTP server"
time="2024-05-09T02:22:01+03:00" level=debug msg="Scheduler: stop"
time="2024-05-09T02:22:01+03:00" level=info msg="Closing Database"
time="2024-05-09T02:22:01+03:00" level=info msg="Navidrome stopped, bye."

time="2024-05-09T02:13:43+03:00" level=info msg="Stopping HTTP server"
time="2024-05-09T02:13:43+03:00" level=debug msg="Scheduler: stop"
time="2024-05-09T02:13:43+03:00" level=debug msg="Stopping trackSwitcher goroutine" device="wasapi/{eebf0aab-21a9-4d68-8759-22f533c960e7}"
time="2024-05-09T02:13:43+03:00" level=info msg="Closing Database"
time="2024-05-09T02:13:43+03:00" level=info msg="Navidrome stopped, bye."

deluan commented 1 week ago

Nice!

The order sometimes differs:

Yes, that's expected, as each subsystem (server, playback, cron, scanner...) run in parallel and also stop in parallel.

I'll wait on @ms140569's review, to be sure I'm not breaking anything else. Then I'll merge the PR and make a new release.

Thanks for the help testing this!

ms140569 commented 1 week ago

@deluan I've reviewed the code: Looks good to me. Passing on the correct context to the player/executor is the best way to approach this. I've smoke-tested it on Mac, but have no Windows to doublecheck. I do not think this should break anything else ... So I would give it a go!

navidrome / navidrome