[Bug]: Jukebox mode under Windows #2767

korzhyc · 2024-01-06T00:30:13Z

I confirm that:

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

Version

0.50.2

Current Behavior

Navidrome successfully launches mpv:

[   0.048][v][cplayer] audio ready
[   0.048][v][cplayer] starting audio playback
[   0.048][v][cplayer] playback restart complete @ 0.000000, audio=playing, video=eof (paused)

That's all, no action. mpv is pending. Subsonic client freezes at the beginning of playback.

Expected Behavior

Proper socket check under Windows.

Steps To Reproduce

No response

Environment

- OS: Windows Server 2022
- Browser: -
- Client: DSub 5.5.3, Ultrasonic 4.8.0

How Navidrome is installed?

Binary (from downloads page)

Configuration

LogLevel = 'info'
DataFolder = '.\data'
MusicFolder = 'F:\Music'
Jukebox.Enabled = true
Jukebox.Devices = [
  ['realtek_spdif', 'wasapi/{eebf0aab-21a9-4d68-8759-22f533c960e7}']
]
MPVPath = 'C:\Srv\Navidrome\jukebox\mpv.com'

Relevant log output

time="2024-01-06T01:50:19+03:00" level=error msg="error or timeout waiting for control socket" error="timeout reached: 3s" socketname="C:\\Users\\MusicSvc\\AppData\\Local\\Temp\\mpv-ctrl-38aef8102d918d23bc960e9c439c1a6d.socket"

Anything else?

https://github.com/natefinch/npipe/blob/v2/README.md

Code of Conduct

I agree to follow Navidrome's Code of Conduct

The text was updated successfully, but these errors were encountered:

apkatsikas · 2024-01-07T20:38:29Z

I can confirm this issue on Windows. If I make a special build and replace os.TempDir() with \\.\pipe\mpvsocket on

navidrome/core/playback/mpv/mpv.go

Line 141 in 6f7b482

return filepath.Join(os.TempDir(), prefix+hex.EncodeToString(randBytes)+suffix)

it fixes the issue. On Windows, I believe you need to use named pipes instead of a real file path in temp for mpv socket control.

apkatsikas · 2024-01-07T21:04:13Z

I will issue a PR for this later today.

Use named pipe for socket path under windows during mpv playback, change function name, unexport function Signed-off-by: apkatsikas <apkatsikas@gmail.com>

korzhyc · 2024-01-07T22:43:29Z

If I make a special build and replace os.TempDir() with \\.\pipe\mpvsocket

This will only change the pipe name.

Start from here:

navidrome/core/playback/mpv/track.go

Line 44 in 6f7b482

err = waitForSocket(tmpSocketName, 3*time.Second, 100*time.Millisecond)

navidrome/core/playback/mpv/track.go

Lines 206 to 212 in 6f7b482

    
           func waitForSocket(path string, timeout time.Duration, pause time.Duration) error { 
        
           	start := time.Now() 
        
           	end := start.Add(timeout) 
        
           	var retries int = 0 
        
           	for { 
        
           		fileInfo, err := os.Stat(path)

It should not be filesystem-related on Windows.

apkatsikas · 2024-01-07T22:56:31Z

I've opened the PR here - #2774

apkatsikas · 2024-01-07T23:03:45Z

If I make a special build and replace os.TempDir() with \\.\pipe\mpvsocket

This will only change the pipe name.

Start from here:

navidrome/core/playback/mpv/track.go

Line 44 in 6f7b482

err = waitForSocket(tmpSocketName, 3*time.Second, 100*time.Millisecond)

navidrome/core/playback/mpv/track.go

Lines 206 to 212 in 6f7b482

func waitForSocket(path string, timeout time.Duration, pause time.Duration) error {

start := time.Now()

end := start.Add(timeout)

var retries int = 0

for {

fileInfo, err := os.Stat(path)

It should not be filesystem-related on Windows.

The doc you've linked with npipe says The address must be of the form \.\pipe<name> for local pipes and \\pipe<name> for remote pipes. - a conventional file path in the temp folder is not accepted when using mpv - which I get into in the PR. I confirmed this allows for playing a track via /rest/jukeboxControl endpoint.

Fix typo Signed-off-by: apkatsikas <apkatsikas@gmail.com>

apkatsikas · 2024-01-08T03:48:47Z

@korzhyc - the GitHub actions bot on this PR provides a binaries.zip that includes a Windows build if you want to give it a try #2774 (comment)

korzhyc · 2024-01-08T11:07:57Z

Yeah, it's working now.

Upd: can we continue here? There's smth wrong going on track switching.... (i'm investigating)

apkatsikas · 2024-01-08T15:38:35Z

Yeah, it's working now.

Upd: can we continue here? There's smth wrong going on track switching.... (i'm investigating)

Definitely let me know what you find.

korzhyc · 2024-01-08T16:43:29Z

If mpv.conf: audio-exclusive=yes is set, Navidrome will panic/crash when the current track ends (however, manual switching is okay):

time="2024-01-08T15:04:58+03:00" level=error msg="Error or timeout waiting for control socket" error="timeout reached: 3s" socketname="\\\\.\\pipe\\mpvsocket\\mpv-ctrl-854f6dd212835b613c41365e95145a3b.socket"
time="2024-01-08T15:04:58+03:00" level=error msg="Error switching track" error="timeout reached: 3s"
panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xc0000005 code=0x0 addr=0x50 pc=0x146f14f]
goroutine 931 [running]:
github.com/navidrome/navidrome/core/playback.(*playbackDevice).trackSwitcherGoroutine(0xc000411e00)
	/github/workspace/core/playback/device.go:272 +0x28f
github.com/navidrome/navidrome/core/playback.(*playbackDevice).Start.func1()
	/github/workspace/core/playback/device.go:110 +0x17
created by github.com/navidrome/navidrome/core/playback.(*playbackDevice).Start in goroutine 119
	/github/workspace/core/playback/device.go:109 +0x189

mpv.log:

[   0.021][e][ao/wasapi] Error initializing device: AUDCLNT_E_DEVICE_IN_USE (0x8889000a)
[   0.022][w][ao/wasapi] Retrying in 1000 ns
...
[   0.043][i][cplayer] Exiting... (Errors when loading file)

And two more things are bothering me...

Playback stops when I manipulate the queue. Is it by design?

This applies to deleting, adding and moving items.
Tested on DSub and Ultrasonic.

time="2024-01-08T18:04:09+03:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 username=admin version=1.2.0
time="2024-01-08T18:04:09+03:00" level=debug msg="Processing GetDevice" user=admin
time="2024-01-08T18:04:09+03:00" level=info msg="JukeboxControl request received" action=set requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 username=admin
time="2024-01-08T18:04:09+03:00" level=debug msg="Processing Set action" device="Name: realtek_spdif, Gain: 1.0000, Loaded track: Name: F:\\Music\\-COLLECT\\Ally Nicholas - All Summer Long [BObbNFMUSiI].opus, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-613eae1c3f5ffd5124d0fd77741e2844.socket" ids="[7ef4534eb2d34ebf12de50d53d677875 226e637624d458bf3c8af9ee8da92802 10ced934565c72282bebffc6b48aff78 c9d0deefd7ac18a82b0ef8a41b95926e]" requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 username=admin
time="2024-01-08T18:04:09+03:00" level=debug msg="Processing Clear action" device="Name: realtek_spdif, Gain: 1.0000, Loaded track: Name: F:\\Music\\-COLLECT\\Ally Nicholas - All Summer Long [BObbNFMUSiI].opus, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-613eae1c3f5ffd5124d0fd77741e2844.socket" requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 username=admin
time="2024-01-08T18:04:09+03:00" level=info msg="paused track"
time="2024-01-08T18:04:09+03:00" level=debug msg="closing resources"
time="2024-01-08T18:04:09+03:00" level=debug msg="sending shutdown command"
time="2024-01-08T18:04:09+03:00" level=info msg="Hitting end-of-stream, signalling on channel"
time="2024-01-08T18:04:09+03:00" level=debug msg="Processing Add action" device="Name: realtek_spdif, Gain: 1.0000, Loaded track: %!s(<nil>)" ids="[7ef4534eb2d34ebf12de50d53d677875 226e637624d458bf3c8af9ee8da92802 10ced934565c72282bebffc6b48aff78 c9d0deefd7ac18a82b0ef8a41b95926e]" requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 username=admin
time="2024-01-08T18:04:09+03:00" level=debug msg="Found mediafile: F:\\Music\\-COLLECT\\Ally Nicholas - All Summer Long [BObbNFMUSiI].opus" requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 username=admin
time="2024-01-08T18:04:09+03:00" level=debug msg="Found mediafile: F:\\Music\\Devil's Trade, The - 2023 - Videkek vannak idebenn [TR24]\\02 - Flashing Through the Lack of Light.flac" requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 username=admin
moved up->
time="2024-01-08T18:04:09+03:00" level=debug msg="Found mediafile: F:\\Music\\-COLLECT\\Ally Nicholas - Seventeen [__ZaTpX1qlo].opus" requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 username=admin
moved down->
time="2024-01-08T18:04:09+03:00" level=debug msg="Found mediafile: F:\\Music\\Aleah - 2020 - Aleah (Bonus Material) [TR24]\\05 - One of Us (Joan Osborne cover 2002).flac" requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 username=admin
time="2024-01-08T18:04:09+03:00" level=debug msg="API: Successful response" body="<subsonic-response xmlns=\"http://subsonic.org/restapi\" status=\"ok\" version=\"1.16.1\" type=\"navidrome\" serverVersion=\"0.50.1-SNAPSHOT (badc0cb5)\" openSubsonic=\"true\"><jukeboxStatus currentIndex=\"0\" playing=\"false\" gain=\"1\"></jukeboxStatus></subsonic-response>" endpoint=/rest/jukeboxControl.view requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 status=OK username=admin
time="2024-01-08T18:04:09+03:00" level=debug msg="HTTP: GET http://10.0.2.11:4533/rest/jukeboxControl.view?u=admin&s=[REDACTED]&t=[REDACTED]&v=1.2.0&c=DSub&action=set&id=7ef4534eb2d34ebf12de50d53d677875&id=226e637624d458bf3c8af9ee8da92802&id=10ced934565c72282bebffc6b48aff78&id=c9d0deefd7ac18a82b0ef8a41b95926e" elapsedTime=5.3ms httpStatus=200 remoteAddr="10.0.2.3:55400" requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 responseSize=257 userAgent=DSub

Bugfeature:

Currently I can control playback from the second client. That's cool!
But one of the clients has an unsynchronized queue. I can pause/resume/switch tracks blindly =)

apkatsikas · 2024-01-08T17:47:59Z

If mpv.conf: audio-exclusive=yes is set, Navidrome will panic/crash when the current track ends (however, manual switching is okay):

time="2024-01-08T15:04:58+03:00" level=error msg="Error or timeout waiting for control socket" error="timeout reached: 3s" socketname="\\\\.\\pipe\\mpvsocket\\mpv-ctrl-854f6dd212835b613c41365e95145a3b.socket"
time="2024-01-08T15:04:58+03:00" level=error msg="Error switching track" error="timeout reached: 3s"
panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xc0000005 code=0x0 addr=0x50 pc=0x146f14f]
goroutine 931 [running]:
github.com/navidrome/navidrome/core/playback.(*playbackDevice).trackSwitcherGoroutine(0xc000411e00)
	/github/workspace/core/playback/device.go:272 +0x28f
github.com/navidrome/navidrome/core/playback.(*playbackDevice).Start.func1()
	/github/workspace/core/playback/device.go:110 +0x17
created by github.com/navidrome/navidrome/core/playback.(*playbackDevice).Start in goroutine 119
	/github/workspace/core/playback/device.go:109 +0x189

mpv.log:

[   0.021][e][ao/wasapi] Error initializing device: AUDCLNT_E_DEVICE_IN_USE (0x8889000a)
[   0.022][w][ao/wasapi] Retrying in 1000 ns
...
[   0.043][i][cplayer] Exiting... (Errors when loading file)

And two more things are bothering me...
Playback stops when I manipulate the queue. Is it by design?

This applies to deleting, adding and moving items. Tested on DSub and Ultrasonic.

time="2024-01-08T18:04:09+03:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 username=admin version=1.2.0
time="2024-01-08T18:04:09+03:00" level=debug msg="Processing GetDevice" user=admin
time="2024-01-08T18:04:09+03:00" level=info msg="JukeboxControl request received" action=set requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 username=admin
time="2024-01-08T18:04:09+03:00" level=debug msg="Processing Set action" device="Name: realtek_spdif, Gain: 1.0000, Loaded track: Name: F:\\Music\\-COLLECT\\Ally Nicholas - All Summer Long [BObbNFMUSiI].opus, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-613eae1c3f5ffd5124d0fd77741e2844.socket" ids="[7ef4534eb2d34ebf12de50d53d677875 226e637624d458bf3c8af9ee8da92802 10ced934565c72282bebffc6b48aff78 c9d0deefd7ac18a82b0ef8a41b95926e]" requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 username=admin
time="2024-01-08T18:04:09+03:00" level=debug msg="Processing Clear action" device="Name: realtek_spdif, Gain: 1.0000, Loaded track: Name: F:\\Music\\-COLLECT\\Ally Nicholas - All Summer Long [BObbNFMUSiI].opus, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-613eae1c3f5ffd5124d0fd77741e2844.socket" requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 username=admin
time="2024-01-08T18:04:09+03:00" level=info msg="paused track"
time="2024-01-08T18:04:09+03:00" level=debug msg="closing resources"
time="2024-01-08T18:04:09+03:00" level=debug msg="sending shutdown command"
time="2024-01-08T18:04:09+03:00" level=info msg="Hitting end-of-stream, signalling on channel"
time="2024-01-08T18:04:09+03:00" level=debug msg="Processing Add action" device="Name: realtek_spdif, Gain: 1.0000, Loaded track: %!s(<nil>)" ids="[7ef4534eb2d34ebf12de50d53d677875 226e637624d458bf3c8af9ee8da92802 10ced934565c72282bebffc6b48aff78 c9d0deefd7ac18a82b0ef8a41b95926e]" requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 username=admin
time="2024-01-08T18:04:09+03:00" level=debug msg="Found mediafile: F:\\Music\\-COLLECT\\Ally Nicholas - All Summer Long [BObbNFMUSiI].opus" requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 username=admin
time="2024-01-08T18:04:09+03:00" level=debug msg="Found mediafile: F:\\Music\\Devil's Trade, The - 2023 - Videkek vannak idebenn [TR24]\\02 - Flashing Through the Lack of Light.flac" requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 username=admin
moved up->
time="2024-01-08T18:04:09+03:00" level=debug msg="Found mediafile: F:\\Music\\-COLLECT\\Ally Nicholas - Seventeen [__ZaTpX1qlo].opus" requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 username=admin
moved down->
time="2024-01-08T18:04:09+03:00" level=debug msg="Found mediafile: F:\\Music\\Aleah - 2020 - Aleah (Bonus Material) [TR24]\\05 - One of Us (Joan Osborne cover 2002).flac" requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 username=admin
time="2024-01-08T18:04:09+03:00" level=debug msg="API: Successful response" body="<subsonic-response xmlns=\"http://subsonic.org/restapi\" status=\"ok\" version=\"1.16.1\" type=\"navidrome\" serverVersion=\"0.50.1-SNAPSHOT (badc0cb5)\" openSubsonic=\"true\"><jukeboxStatus currentIndex=\"0\" playing=\"false\" gain=\"1\"></jukeboxStatus></subsonic-response>" endpoint=/rest/jukeboxControl.view requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 status=OK username=admin
time="2024-01-08T18:04:09+03:00" level=debug msg="HTTP: GET http://10.0.2.11:4533/rest/jukeboxControl.view?u=admin&s=[REDACTED]&t=[REDACTED]&v=1.2.0&c=DSub&action=set&id=7ef4534eb2d34ebf12de50d53d677875&id=226e637624d458bf3c8af9ee8da92802&id=10ced934565c72282bebffc6b48aff78&id=c9d0deefd7ac18a82b0ef8a41b95926e" elapsedTime=5.3ms httpStatus=200 remoteAddr="10.0.2.3:55400" requestId=WIN-6H9506BP7VG/HNuiBJgYLY-000289 responseSize=257 userAgent=DSub

Bugfeature:

Currently I can control playback from the second client. That's cool! But one of the clients has an unsynchronized queue. I can pause/resume/switch tracks blindly =)

I can confirm a similar issue with exclusive mode in my Windows. Playback fails with INFO log Hitting end-of-stream, signalling on channel, but does not crash (in my environment). Exclusive mode does not exhibit this issue in Linux build. I do not observe the issue in Windows when exclusive mode is off. Sounds like this could be filed as a new issue specific to exclusive mode on Windows where we can both provide details. I also observed that in non-exclusive Windows mode, I see level=debug msg="Track switching detected" - while this never happens in Windows exclusive mode. Something to look at here -

navidrome/core/playback/device.go

Line 259 in 6f7b482

log.Debug("Track switching detected")

I can not recreate your issue with the track stopping during queue manipulation. I used API endpoints for jukebox control during playback for action=add and action=remove in Windows. Playback continued as expected. I think this can be a new issue - it might be specific to how your mobile client interacts with Navidrome, or maybe something specific in your setup/environment that we will need to figure out so we can re-create.

Regarding your bugfeature issue I am not totally sure what the suggestion is - feel free to submit an issue for it, though.

Early return for Close on Windows Signed-off-by: apkatsikas <apkatsikas@gmail.com>

Merge master and move logic into utils function Signed-off-by: apkatsikas <apkatsikas@gmail.com>

Update import and run prettier Signed-off-by: apkatsikas <apkatsikas@gmail.com>

Update function name Signed-off-by: apkatsikas <apkatsikas@gmail.com>

Create track_close files for both platforms and move MpvTrack Close into new file Signed-off-by: apkatsikas <apkatsikas@gmail.com>

Create SocketName function for both platforms, restore name of TempFileName Signed-off-by: apkatsikas <apkatsikas@gmail.com>

Add missing params to SocketName on windows Signed-off-by: apkatsikas <apkatsikas@gmail.com>

* bug(core/playback/mpv): jukebox mode under windows - #2767 Use named pipe for socket path under windows during mpv playback, change function name, unexport function Signed-off-by: apkatsikas <apkatsikas@gmail.com> * bug(core/playback/mpv): jukebox mode under windows - #2767 Fix typo Signed-off-by: apkatsikas <apkatsikas@gmail.com> * bug(core/playback/mpv): jukebox mode under windows - #2767 Early return for Close on Windows Signed-off-by: apkatsikas <apkatsikas@gmail.com> * bug(core/playback/mpv): jukebox mode under windows - #2767 Update import and run prettier Signed-off-by: apkatsikas <apkatsikas@gmail.com> * bug(core/playback/mpv): jukebox mode under windows - #2767 Update function name Signed-off-by: apkatsikas <apkatsikas@gmail.com> * bug(core/playback/mpv): jukebox mode under windows - #2767 Create track_close files for both platforms and move MpvTrack Close into new file Signed-off-by: apkatsikas <apkatsikas@gmail.com> * bug(core/playback/mpv): jukebox mode under windows - #2767 Create SocketName function for both platforms, restore name of TempFileName Signed-off-by: apkatsikas <apkatsikas@gmail.com> * bug(core/playback/mpv): jukebox mode under windows - #2767 Add missing params to SocketName on windows Signed-off-by: apkatsikas <apkatsikas@gmail.com> * Unexport SocketName, use socketName in NewTrack --------- Signed-off-by: apkatsikas <apkatsikas@gmail.com>

deluan · 2024-04-14T18:01:07Z

Hey @korzhyc, now that @apkatsikas's PR was merged, can you try the latest from develop and check if it solves your issues?

korzhyc · 2024-04-19T02:27:45Z

0.50.1-SNAPSHOT (badc0cb) - the version I still use.

0.51.1-SNAPSHOT (bcec15d) - the bug about opening the socket has been resolved.
But when I switch tracks manually, something wrong happens.
The old process is paused and left hanging...

When I switch to the next track:

time="2024-04-19T04:27:10+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:53232" requestId=WIN-6H9506BP7VG/VvQMwbjBtF-000032 responseSize=215 userAgent=okhttp/4.11.0
time="2024-04-19T04:27:11+03:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=Ultrasonic requestId=WIN-6H9506BP7VG/VvQMwbjBtF-000033 username=guest version=1.16.0
time="2024-04-19T04:27:11+03:00" level=debug msg="Processing GetDevice" user=guest
time="2024-04-19T04:27:11+03:00" level=info msg="JukeboxControl request received" action=skip requestId=WIN-6H9506BP7VG/VvQMwbjBtF-000033 username=guest
time="2024-04-19T04:27:11+03:00" level=debug msg="Processing Skip action" device="Name: realtek_spdif, Gain: 1.0000, Loaded track: Name: F:\\Music\\Ambeon - 2001 - Fate Of A Dreamer [RE RM 2012]\\1.12 - Merry-Go-Round.flac, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-68a7c70a-4458-4d47-90e0-034bc214091f.socket" index=12 offset=0 requestId=WIN-6H9506BP7VG/VvQMwbjBtF-000033 username=guest
time="2024-04-19T04:27:11+03:00" level=debug msg="Checking if track is playing" track="Name: F:\\Music\\Ambeon - 2001 - Fate Of A Dreamer [RE RM 2012]\\1.12 - Merry-Go-Round.flac, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-68a7c70a-4458-4d47-90e0-034bc214091f.socket"
time="2024-04-19T04:27:11+03:00" level=debug msg="Pausing track" track="Name: F:\\Music\\Ambeon - 2001 - Fate Of A Dreamer [RE RM 2012]\\1.12 - Merry-Go-Round.flac, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-68a7c70a-4458-4d47-90e0-034bc214091f.socket"
time="2024-04-19T04:27:11+03:00" level=debug msg="Loading track" mediaType=audio/flac trackPath="F:\\Music\\Ambeon - 2001 - Fate Of A Dreamer [RE RM 2012]\\1.13 - High (Remix).flac"
time="2024-04-19T04:27:11+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\\Ambeon - 2001 - Fate Of A Dreamer [RE RM 2012]\\1.13 - High (Remix).flac --input-ipc-server=\\\\.\\pipe\\mpvsocket\\mpv-ctrl-cef29840-b523-4443-81f5-4089eeb9fa14.socket]"
time="2024-04-19T04:27:11+03:00" level=debug msg="Socket found" retries=1 waitTime=101.9ms
time="2024-04-19T04:27:11+03:00" level=debug msg="Setting position" offset=0 track="Name: F:\\Music\\Ambeon - 2001 - Fate Of A Dreamer [RE RM 2012]\\1.13 - High (Remix).flac, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-cef29840-b523-4443-81f5-4089eeb9fa14.socket"
time="2024-04-19T04:27:11+03:00" level=debug msg="No position difference, skipping operation" track="Name: F:\\Music\\Ambeon - 2001 - Fate Of A Dreamer [RE RM 2012]\\1.13 - High (Remix).flac, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-cef29840-b523-4443-81f5-4089eeb9fa14.socket"
time="2024-04-19T04:27:11+03:00" level=debug msg="Processing Start action" device="Name: realtek_spdif, Gain: 1.0000, Loaded track: Name: F:\\Music\\Ambeon - 2001 - Fate Of A Dreamer [RE RM 2012]\\1.13 - High (Remix).flac, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-cef29840-b523-4443-81f5-4089eeb9fa14.socket" requestId=WIN-6H9506BP7VG/VvQMwbjBtF-000033 username=guest
time="2024-04-19T04:27:11+03:00" level=debug msg="Checking if track is playing" track="Name: F:\\Music\\Ambeon - 2001 - Fate Of A Dreamer [RE RM 2012]\\1.13 - High (Remix).flac, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-cef29840-b523-4443-81f5-4089eeb9fa14.socket"
time="2024-04-19T04:27:11+03:00" level=debug msg="Unpausing track" track="Name: F:\\Music\\Ambeon - 2001 - Fate Of A Dreamer [RE RM 2012]\\1.13 - High (Remix).flac, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-cef29840-b523-4443-81f5-4089eeb9fa14.socket"
time="2024-04-19T04:27:11+03:00" level=debug msg="Checking if track is playing" track="Name: F:\\Music\\Ambeon - 2001 - Fate Of A Dreamer [RE RM 2012]\\1.13 - High (Remix).flac, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-cef29840-b523-4443-81f5-4089eeb9fa14.socket"
time="2024-04-19T04:27:11+03:00" level=debug msg="Checking if track is playing" track="Name: F:\\Music\\Ambeon - 2001 - Fate Of A Dreamer [RE RM 2012]\\1.13 - High (Remix).flac, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-cef29840-b523-4443-81f5-4089eeb9fa14.socket"
time="2024-04-19T04:27:11+03:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=WIN-6H9506BP7VG/VvQMwbjBtF-000033 status=OK username=guest

mpv.log from the old/hanging process:

...
[ 284.204][v][cplayer] playback restart complete @ 115.999993, audio=playing, video=eof (paused)
[ 285.207][d][ao/wasapi] Thread Resume
[ 285.207][d][ao/wasapi] Thread Reset
[ 285.207][v][cplayer] Set property: pause=false -> 1
[ 341.126][v][cplayer] Set property: pause=true -> 1
[ 341.126][d][ao/wasapi] Thread Reset
[EOF]

When I try to kill extra mpv processes:

time="2024-04-19T04:43:48+03:00" level=info msg="Hitting end-of-stream, signalling on channel"
time="2024-04-19T04:43:48+03:00" level=debug msg="Track switching detected"
time="2024-04-19T04:43:48+03:00" level=debug msg="Switching to next song" queue="#Items: 27, idx: 13, files: 0:F:\\Music\\Ambeon - 2001 - Fate Of A Dreamer [RE RM 2012]\\1.01 - Estranged.flac 1: [REDACTED] "
time="2024-04-19T04:43:48+03:00" level=debug msg="Loading track" mediaType=audio/flac trackPath="F:\\Music\\Ambeon - 2001 - Fate Of A Dreamer [RE RM 2012]\\2.01 - Actual Fantasy.flac"
time="2024-04-19T04:43:48+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\\Ambeon - 2001 - Fate Of A Dreamer [RE RM 2012]\\2.01 - Actual Fantasy.flac --input-ipc-server=\\\\.\\pipe\\mpvsocket\\mpv-ctrl-2348d8e3-17c1-4007-9236-5cd120ad8aa1.socket]"
time="2024-04-19T04:43:49+03:00" level=debug msg="Socket found" retries=1 waitTime=109.3ms
time="2024-04-19T04:43:49+03:00" level=debug msg="Unpausing track" track="Name: F:\\Music\\Ambeon - 2001 - Fate Of A Dreamer [RE RM 2012]\\2.01 - Actual Fantasy.flac, Socket: \\\\.\\pipe\\mpvsocket\\mpv-ctrl-2348d8e3-17c1-4007-9236-5cd120ad8aa1.socket"

korzhyc · 2024-04-19T03:04:46Z

navidrome/core/playback/mpv/track_close_win.go

Lines 5 to 8 in c2f932c

    
           func (t *MpvTrack) Close() { 
        
           	// Windows automatically handles closing 
        
           	// and cleaning up named pipe 
        
           }

... it handles, if you terminate the process.

deluan · 2024-04-19T13:21:42Z

@korzhyc Can you please try this build?

navidrome.exe.zip

korzhyc · 2024-04-19T14:38:15Z

0.51.1-SNAPSHOT (068c1e9) - this one is okay

deluan · 2024-04-19T14:51:53Z

0.51.1-SNAPSHOT (068c1e9) - this one is okay

@korzhyc , are you sure? The build I posted was a local fix I didn't push to GitHub, so the version you linked (0.51.1-SNAPSHOT (068c1e9)) should behave exactly the same as the one you tried before (0.51.1-SNAPSHOT (bcec15d))

korzhyc · 2024-04-19T14:58:00Z

0_68c1e9a: that one =)

deluan · 2024-04-19T16:23:16Z

Just to be sure: you downlaoded and tested the binary I posted in my comment above, right?

Anyway, I pushed the fix and the develop build (and docker images) should have the fix in place soon.

Thanks for validating it.

korzhyc · 2024-04-21T14:06:56Z

Rechecked the last one, jtbs.
0.51.1-SNAPSHOT (6dcfe4d) - whatever that means =)

korzhyc · 2024-04-21T17:24:58Z

[one moment later]

I caught this heisenbug:
When stopping service during jukebox playback, sometimes mpv process restarts and stays running.

Normal shutdown:

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 was killed? no "Closing resources" msg

Bugged shutdown (or vice versa?):

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."

deluan · 2024-04-26T01:00:41Z

Seems that the PlaybackServer is not handling context cancelation correctly.... This is a related but different issue. Can you please open a new issue in GH with the details?

Thanks!

deluan · 2024-04-27T18:08:43Z

Thanks for opening #2978. As it is a different issue, I'll close this one.

korzhyc added bug triage New bug reports that need to be evaluated labels Jan 6, 2024

apkatsikas mentioned this issue Jan 7, 2024

bug(core/playback/mpv): jukebox mode under windows - #2767 #2774

Merged

apkatsikas added a commit to apkatsikas/navidrome that referenced this issue Jan 7, 2024

bug(core/playback/mpv): jukebox mode under windows - navidrome#2767

b97bf61

Fix typo Signed-off-by: apkatsikas <apkatsikas@gmail.com>

apkatsikas added a commit to apkatsikas/navidrome that referenced this issue Apr 12, 2024

bug(core/playback/mpv): jukebox mode under windows - navidrome#2767

93bb3ce

Early return for Close on Windows Signed-off-by: apkatsikas <apkatsikas@gmail.com>

apkatsikas added a commit to apkatsikas/navidrome that referenced this issue Apr 12, 2024

bug(core/playback/mpv): jukebox mode under windows - navidrome#2767

0d5d74b

Merge master and move logic into utils function Signed-off-by: apkatsikas <apkatsikas@gmail.com>

apkatsikas added a commit to apkatsikas/navidrome that referenced this issue Apr 12, 2024

bug(core/playback/mpv): jukebox mode under windows - navidrome#2767

f3b54f0

Update import and run prettier Signed-off-by: apkatsikas <apkatsikas@gmail.com>

apkatsikas added a commit to apkatsikas/navidrome that referenced this issue Apr 12, 2024

bug(core/playback/mpv): jukebox mode under windows - navidrome#2767

243b529

Update function name Signed-off-by: apkatsikas <apkatsikas@gmail.com>

apkatsikas added a commit to apkatsikas/navidrome that referenced this issue Apr 14, 2024

bug(core/playback/mpv): jukebox mode under windows - navidrome#2767

e7186a4

Create SocketName function for both platforms, restore name of TempFileName Signed-off-by: apkatsikas <apkatsikas@gmail.com>

apkatsikas added a commit to apkatsikas/navidrome that referenced this issue Apr 14, 2024

bug(core/playback/mpv): jukebox mode under windows - navidrome#2767

e8a6042

Add missing params to SocketName on windows Signed-off-by: apkatsikas <apkatsikas@gmail.com>

deluan added a commit that referenced this issue Apr 19, 2024

Fix issue in #2767 (comment)

9aeaaa6

deluan mentioned this issue Apr 27, 2024

[Bug]: Jukebox playback graceful shutdown #2978

Closed

3 tasks

deluan closed this as completed Apr 27, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Bug]: Jukebox mode under Windows #2767

[Bug]: Jukebox mode under Windows #2767

korzhyc commented Jan 6, 2024 •

edited

apkatsikas commented Jan 7, 2024

apkatsikas commented Jan 7, 2024

korzhyc commented Jan 7, 2024 •

edited

apkatsikas commented Jan 7, 2024

apkatsikas commented Jan 7, 2024

apkatsikas commented Jan 8, 2024

korzhyc commented Jan 8, 2024 •

edited

apkatsikas commented Jan 8, 2024

korzhyc commented Jan 8, 2024 •

edited

apkatsikas commented Jan 8, 2024 •

edited

deluan commented Apr 14, 2024

korzhyc commented Apr 19, 2024

korzhyc commented Apr 19, 2024

deluan commented Apr 19, 2024

korzhyc commented Apr 19, 2024

deluan commented Apr 19, 2024

korzhyc commented Apr 19, 2024 •

edited

deluan commented Apr 19, 2024 •

edited

korzhyc commented Apr 21, 2024

korzhyc commented Apr 21, 2024 •

edited

deluan commented Apr 26, 2024

deluan commented Apr 27, 2024

[Bug]: Jukebox mode under Windows #2767

[Bug]: Jukebox mode under Windows #2767

Comments

korzhyc commented Jan 6, 2024 • edited

I confirm that:

Version

Current Behavior

Expected Behavior

Steps To Reproduce

Environment

How Navidrome is installed?

Configuration

Relevant log output

Anything else?

Code of Conduct

apkatsikas commented Jan 7, 2024

apkatsikas commented Jan 7, 2024

korzhyc commented Jan 7, 2024 • edited

apkatsikas commented Jan 7, 2024

apkatsikas commented Jan 7, 2024

apkatsikas commented Jan 8, 2024

korzhyc commented Jan 8, 2024 • edited

apkatsikas commented Jan 8, 2024

korzhyc commented Jan 8, 2024 • edited

apkatsikas commented Jan 8, 2024 • edited

deluan commented Apr 14, 2024

korzhyc commented Apr 19, 2024

korzhyc commented Apr 19, 2024

deluan commented Apr 19, 2024

korzhyc commented Apr 19, 2024

deluan commented Apr 19, 2024

korzhyc commented Apr 19, 2024 • edited

deluan commented Apr 19, 2024 • edited

korzhyc commented Apr 21, 2024

korzhyc commented Apr 21, 2024 • edited

deluan commented Apr 26, 2024

deluan commented Apr 27, 2024

korzhyc commented Jan 6, 2024 •

edited

korzhyc commented Jan 7, 2024 •

edited

korzhyc commented Jan 8, 2024 •

edited

korzhyc commented Jan 8, 2024 •

edited

apkatsikas commented Jan 8, 2024 •

edited

korzhyc commented Apr 19, 2024 •

edited

deluan commented Apr 19, 2024 •

edited

korzhyc commented Apr 21, 2024 •

edited