[Bug]: mpv errors when trying to use jukebox mode

pruperting commented 2 months 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.52.5

Current Behavior

When trying to use Jukebox mode it doesn't work and I see errors in the logs. These errors appear to be linked to the file path that is passed to mpv not being quoted to deal with white spaces - BUT I might be wrong.

If I paste the mpv command listed in the logs, I get an error. If I then put quotes around the file path in the same command, mpv does not give an error and it plays. My current setting attempts to use snapcast, but I get the same error with the MPVTemplate option disabled.

Expected Behavior

I am expecting jukebox mode to work with no errors.

Steps To Reproduce

Enable jukebox mode
Use DSub to play a track, selecting Jukebox as an output
Fail

Environment

- OS: dietpi: v9.7.1
- Browser: Chrome
- Client: Dsub Android 13

How Navidrome is installed?

Package

Configuration

DataFolder = '/mnt/dietpi_userdata/navidrome/data'
MusicFolder = '/mnt/sda/FLAC'
ImageCacheSize = '1000MiB'

LogLevel = 'debug'
SessionTimeout = '24h'
AuthRequestLimit = '5'
AuthWindowLength = '20s'
ScanSchedule = '@every 24h'
EnableLogRedacting = false
Scanner.Extractor = 'taglib'

CoverJpegQuality = '75'
CoverArtPriority = 'folder.*, Folder.*, cover.*. Cover.*, embedded, external'

LastFM.Enabled = true
LastFM.ApiKey = 'xx'
LastFM.Secret = 'xx'

Jukebox.Enabled = true
MPVPath = '/usr/bin/mpv'
Jukebox.Devices = [
    [ "internal",     "alsa/plughw:CARD=DAC,DEV=0" ]
]
Jukebox.Default = 'internal'
MPVCmdTemplate = 'mpv --no-audio-display --pause %f --input-ipc-server=%s --audio-channels=stereo --audio-samplerate=48000 --audio-format=s16 --ao=pcm --ao-pcm-file=/tmp/mpd'

EnableTranscodingConfig = true

Relevant log output

Sep 11 22:18:53 DietPi navidrome[13069]: time="2024-09-11T22:18:53+01:00" level=debug msg="Loading track" mediaType=audio/flac trackPath="/mnt/sda/FLAC/Acoustic/00s/Aqualung/09 Gentle.flac"
Sep 11 22:18:53 DietPi navidrome[13069]: time="2024-09-11T22:18:53+01:00" level=debug msg="Executing mpv command" cmd="[/usr/bin/mpv --no-audio-display --pause /mnt/sda/FLAC/Acoustic/00s/Aqualung/09 Gentle.flac --input-ipc-server=/tmp/mpv-ctrl-3ca738b3-ba30-4104-9d09-3a9ae86bed00.socket --audio-channels=stereo --audio-samplerate=48000 --audio-format=s16 --ao=pcm --ao-pcm-file=/tmp/mpd]"
Sep 11 22:18:53 DietPi navidrome[13069]: time="2024-09-11T22:18:53+01:00" level=debug msg="API: Successful response" endpoint=/rest/scrobble.view requestId=DietPi/XTbFYszRdL-000190 status=OK
Sep 11 22:18:53 DietPi navidrome[13069]: time="2024-09-11T22:18:53+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/scrobble.view?u=prupert&s=7a7kijec6qc8plkj4jdd8rl658&t=5c0b4e312a81e238a3582ed365aeac38&v=1.2.0&c=DSub&id=1052077f64bde5a67e41b87cbfabc0be&submission=true" elapsedTime=54.8ms httpStatus=200 remoteAddr="192.168.1.44:43004" requestId=DietPi/XTbFYszRdL-000190 responseSize=175 userAgent=DSub
Sep 11 22:18:53 DietPi navidrome[13069]: time="2024-09-11T22:18:53+01:00" level=debug msg="API: New request /rest/savePlayQueue.view" client=DSub requestId=DietPi/XTbFYszRdL-000192 username=prupert version=1.2.0
Sep 11 22:18:53 DietPi navidrome[13069]: time="2024-09-11T22:18:53+01:00" level=debug msg="API: Successful response" endpoint=/rest/savePlayQueue.view requestId=DietPi/XTbFYszRdL-000192 status=OK
Sep 11 22:18:53 DietPi navidrome[13069]: time="2024-09-11T22:18:53+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/savePlayQueue.view?u=prupert&s=7a7kijec6qc8plkj4jdd8rl658&t=5c0b4e312a81e238a3582ed365aeac38&v=1.2.0&c=DSub&id=beaa5f9dc33c64dbc4218501b9106da8&id=da1e5cebc1954fed60e12f8a5e0f0947&id=cb3796d55c7a504ee3b03bf35602b4ba&id=07049ee9fd7b730f3c11b8a50bfff725&id=9eeaa735a656e54f20720ef02defaac0&id=3ee1f8f66d108fa4ff7685bcec77f263&id=4803a716723f481ee785c731885b379f&id=c63fbaece2398b0559a1fe4a02a9c532&id=1052077f64bde5a67e41b87cbfabc0be&id=2e35d478498d3b5dc025bdf98ad766f4&id=ed0bab09eefbe8e9082efcca3a3def3b&current=1052077f64bde5a67e41b87cbfabc0be&position=0" elapsedTime=12.1ms httpStatus=200 remoteAddr="192.168.1.44:43012" requestId=DietPi/XTbFYszRdL-000192 responseSize=175 userAgent=DSub
Sep 11 22:18:54 DietPi navidrome[13069]: time="2024-09-11T22:18:54+01:00" level=debug msg="Socket found" retries=9 waitTime=908.7ms
Sep 11 22:18:54 DietPi navidrome[13069]: time="2024-09-11T22:18:54+01:00" level=debug msg="Setting volume" track="Name: /mnt/sda/FLAC/Acoustic/00s/Aqualung/09 Gentle.flac, Socket: /tmp/mpv-ctrl-3ca738b3-ba30-4104-9d09-3a9ae86bed00.socket" volume=1
Sep 11 22:18:54 DietPi navidrome[13069]: time="2024-09-11T22:18:54+01:00" level=debug msg="Setting position" offset=0 track="Name: /mnt/sda/FLAC/Acoustic/00s/Aqualung/09 Gentle.flac, Socket: /tmp/mpv-ctrl-3ca738b3-ba30-4104-9d09-3a9ae86bed00.socket"
Sep 11 22:18:54 DietPi navidrome[13069]: time="2024-09-11T22:18:54+01:00" level=debug msg="Got mpv error, retrying..." error="mpv error: property unavailable" retries=1

Anything else?

No response

Code of Conduct

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

pruperting commented 2 months ago

Right, some developments, messing around with using ' and " in the config, I have removed this error, but jukebox mode + snapcast still not working:

Sep 11 22:58:10 DietPi navidrome[14269]: time="2024-09-11T22:58:10+01:00" level=info msg="JukeboxControl request received" action=skip requestId=DietPi/VPZ5qO11jW-000005
Sep 11 22:58:10 DietPi navidrome[14269]: time="2024-09-11T22:58:10+01:00" level=debug msg="Processing Skip action" device="Name: internal, Gain: 1.0000, Loaded track: %!s(<nil>)" index=0 offset=0 requestId=DietPi/VPZ5qO11jW-000005
Sep 11 22:58:10 DietPi navidrome[14269]: time="2024-09-11T22:58:10+01:00" level=debug msg="Loading track" mediaType=audio/flac trackPath="/mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac"
Sep 11 22:58:10 DietPi navidrome[14269]: time="2024-09-11T22:58:10+01:00" level=info msg="Found mpv" path=/usr/bin/mpv
Sep 11 22:58:10 DietPi navidrome[14269]: time="2024-09-11T22:58:10+01:00" level=debug msg="Executing mpv command" cmd="[/usr/bin/mpv --no-audio-display --pause '/mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac' --input-ipc-server=/tmp/mpv-ctrl-7b72e56c-ff14-4bd7-aa1e-e9cd9696fd41.socket --audio-channels=stereo --audio-samplerate=48000 --audio-format=s16 --ao=pcm --ao-pcm-file=/tmp/mpd]"
Sep 11 22:58:10 DietPi navidrome[14269]: time="2024-09-11T22:58:10+01:00" level=debug msg="API: New request /rest/savePlayQueue.view" client=DSub requestId=DietPi/VPZ5qO11jW-000006 username=prupert version=1.2.0
Sep 11 22:58:10 DietPi navidrome[14269]: time="2024-09-11T22:58:10+01:00" level=debug msg="API: Successful response" endpoint=/rest/scrobble.view requestId=DietPi/VPZ5qO11jW-000004 status=OK
Sep 11 22:58:10 DietPi navidrome[14269]: time="2024-09-11T22:58:10+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/scrobble.view?u=prupert&s=7a7kijec6qc8plkj4jdd8rl658&t=5c0b4e312a81e238a3582ed365aeac38&v=1.2.0&c=DSub&id=f9aa22fc5662d9f30ba40b117c729047&submission=false" elapsedTime=87.3ms httpStatus=200 remoteAddr="192.168.1.44:43514" requestId=DietPi/VPZ5qO11jW-000004 responseSize=175 userAgent=DSub
Sep 11 22:58:10 DietPi navidrome[14269]: time="2024-09-11T22:58:10+01:00" level=debug msg="API: Successful response" endpoint=/rest/savePlayQueue.view requestId=DietPi/VPZ5qO11jW-000006 status=OK
Sep 11 22:58:10 DietPi navidrome[14269]: time="2024-09-11T22:58:10+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/savePlayQueue.view?u=prupert&s=7a7kijec6qc8plkj4jdd8rl658&t=5c0b4e312a81e238a3582ed365aeac38&v=1.2.0&c=DSub&id=f9aa22fc5662d9f30ba40b117c729047&id=a77204808c96d2739d055a98b26901a3&id=9e32bfe65f74402bda36a1a09012f53d&id=bffc98fb978b8a73eef781bb92a3ed46&id=aaf4e847fa4137cebb193f8661f87dd9&id=54759f620e82720d81e8edb1badf07a5&id=4255c3fc5b1a453e49bbc88d20832fc9&id=9ad15f90a1bf3ebf7d4daba7e2c7ef8c&current=f9aa22fc5662d9f30ba40b117c729047&position=0" elapsedTime=35.3ms httpStatus=200 remoteAddr="192.168.1.44:43516" requestId=DietPi/VPZ5qO11jW-000006 responseSize=175 userAgent=DSub
Sep 11 22:58:11 DietPi navidrome[14269]: time="2024-09-11T22:58:11+01:00" level=debug msg="Socket found" retries=9 waitTime=907ms
Sep 11 22:58:11 DietPi navidrome[14269]: time="2024-09-11T22:58:11+01:00" level=debug msg="Setting volume" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-7b72e56c-ff14-4bd7-aa1e-e9cd9696fd41.socket" volume=1
Sep 11 22:58:11 DietPi navidrome[14269]: time="2024-09-11T22:58:11+01:00" level=info msg="Hitting end-of-stream, signalling on channel"
Sep 11 22:58:11 DietPi navidrome[14269]: time="2024-09-11T22:58:11+01:00" level=error msg="Error setting volume" error="trying to send command on closed mpv client" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-7b72e56c-ff14-4bd7-aa1e-e9cd9696fd41.socket" volume=1
Sep 11 22:58:11 DietPi navidrome[14269]: time="2024-09-11T22:58:11+01:00" level=debug msg="Setting position" offset=0 track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-7b72e56c-ff14-4bd7-aa1e-e9cd9696fd41.socket"
Sep 11 22:58:11 DietPi navidrome[14269]: time="2024-09-11T22:58:11+01:00" level=error msg="Error getting position in track" error="trying to send command on closed mpv client" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-7b72e56c-ff14-4bd7-aa1e-e9cd9696fd41.socket"
Sep 11 22:58:11 DietPi navidrome[14269]: time="2024-09-11T22:58:11+01:00" level=debug msg="No position difference, skipping operation" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-7b72e56c-ff14-4bd7-aa1e-e9cd9696fd41.socket"
Sep 11 22:58:11 DietPi navidrome[14269]: time="2024-09-11T22:58:11+01:00" level=error msg="Error getting position in track" error="trying to send command on closed mpv client" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-7b72e56c-ff14-4bd7-aa1e-e9cd9696fd41.socket"
Sep 11 22:58:11 DietPi navidrome[14269]: time="2024-09-11T22:58:11+01:00" level=debug msg="Checking if track is playing" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-7b72e56c-ff14-4bd7-aa1e-e9cd9696fd41.socket"
Sep 11 22:58:11 DietPi navidrome[14269]: time="2024-09-11T22:58:11+01:00" level=error msg="Problem getting paused status" error="trying to send command on closed mpv client" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-7b72e56c-ff14-4bd7-aa1e-e9cd9696fd41.socket"
Sep 11 22:58:11 DietPi navidrome[14269]: time="2024-09-11T22:58:11+01:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=DietPi/VPZ5qO11jW-000005 status=OK
Sep 11 22:58:11 DietPi navidrome[14269]: time="2024-09-11T22:58:11+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/jukeboxControl.view?u=prupert&s=7a7kijec6qc8plkj4jdd8rl658&t=5c0b4e312a81e238a3582ed365aeac38&v=1.2.0&c=DSub&action=skip&index=0&offset=0" elapsedTime=933.9ms httpStatus=200 remoteAddr="192.168.1.44:43512" requestId=DietPi/VPZ5qO11jW-000005 responseSize=248 userAgent=DSub
Sep 11 22:58:14 DietPi navidrome[14269]: time="2024-09-11T22:58:14+01:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=DietPi/VPZ5qO11jW-000007 username=prupert version=1.2.0

Updated relevant section of config file:

Jukebox.Enabled = true
MPVPath = '/usr/bin/mpv'
Jukebox.Devices = [
    [ "internal",     "alsa/plughw:CARD=DAC,DEV=0" ]
]
Jukebox.Default = 'internal'
MPVCmdTemplate = "mpv --no-audio-display --pause '%f' --input-ipc-server=%s --audio-channels=stereo --audio-samplerate=48000 --audio-format=s16 --ao=pcm --ao-pcm-file=/tmp/mpd"

EnableTranscodingConfig = true

pruperting commented 2 months ago

Have now deactivated snapserver streaming and I still get errors:

Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=DietPi/EcCLcxkngL-000207 status=OK
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="API: Successful response" endpoint=/rest/scrobble.view requestId=DietPi/EcCLcxkngL-000208 status=OK
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/jukeboxControl.view?u=prupert&s=7a7kijec6qc8plkj4jdd8rl658&t=5c0b4e312a81e238a3582ed365aeac38&v=1.2.0&c=DSub&action=set&id=f9aa22fc5662d9f30ba40b117c729047&id=a77204808c96d2739d055a98b26901a3&id=9e32bfe65f74402bda36a1a09012f53d&id=bffc98fb978b8a73eef781bb92a3ed46&id=aaf4e847fa4137cebb193f8661f87dd9&id=54759f620e82720d81e8edb1badf07a5&id=4255c3fc5b1a453e49bbc88d20832fc9&id=9ad15f90a1bf3ebf7d4daba7e2c7ef8c" elapsedTime=115.1ms httpStatus=200 remoteAddr="192.168.1.44:40710" requestId=DietPi/EcCLcxkngL-000207 responseSize=248 userAgent=DSub
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/scrobble.view?u=prupert&s=7a7kijec6qc8plkj4jdd8rl658&t=5c0b4e312a81e238a3582ed365aeac38&v=1.2.0&c=DSub&id=f9aa22fc5662d9f30ba40b117c729047&submission=false" elapsedTime=55.4ms httpStatus=200 remoteAddr="192.168.1.44:40736" requestId=DietPi/EcCLcxkngL-000208 responseSize=175 userAgent=DSub
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=DietPi/EcCLcxkngL-000209 username=prupert version=1.2.0
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="Processing GetDevice" user=prupert
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=info msg="JukeboxControl request received" action=skip requestId=DietPi/EcCLcxkngL-000209
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="Processing Skip action" device="Name: internal, Gain: 1.0000, Loaded track: %!s(<nil>)" index=0 offset=0 requestId=DietPi/EcCLcxkngL-000209
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="Loading track" mediaType=audio/flac trackPath="/mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac"
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="Executing mpv command" cmd="[/usr/bin/mpv --audio-device=alsa/plughw:CARD=DAC,DEV=0 --no-audio-display --pause /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac --input-ipc-server=/tmp/mpv-ctrl-c9960aaf-d9c4-4e21-99d9-5ed1da374aff.socket]"
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="API: New request /rest/savePlayQueue.view" client=DSub requestId=DietPi/EcCLcxkngL-000210 username=prupert version=1.2.0
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="API: Successful response" endpoint=/rest/savePlayQueue.view requestId=DietPi/EcCLcxkngL-000210 status=OK
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/savePlayQueue.view?u=prupert&s=7a7kijec6qc8plkj4jdd8rl658&t=5c0b4e312a81e238a3582ed365aeac38&v=1.2.0&c=DSub&id=f9aa22fc5662d9f30ba40b117c729047&id=a77204808c96d2739d055a98b26901a3&id=9e32bfe65f74402bda36a1a09012f53d&id=bffc98fb978b8a73eef781bb92a3ed46&id=aaf4e847fa4137cebb193f8661f87dd9&id=54759f620e82720d81e8edb1badf07a5&id=4255c3fc5b1a453e49bbc88d20832fc9&id=9ad15f90a1bf3ebf7d4daba7e2c7ef8c&current=f9aa22fc5662d9f30ba40b117c729047&position=0" elapsedTime=10.1ms httpStatus=200 remoteAddr="192.168.1.44:40736" requestId=DietPi/EcCLcxkngL-000210 responseSize=175 userAgent=DSub
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="Socket found" retries=8 waitTime=806ms
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="Setting volume" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-c9960aaf-d9c4-4e21-99d9-5ed1da374aff.socket" volume=1
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="Setting position" offset=0 track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-c9960aaf-d9c4-4e21-99d9-5ed1da374aff.socket"
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="Got mpv error, retrying..." error="mpv error: property unavailable" retries=1
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="No position difference, skipping operation" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-c9960aaf-d9c4-4e21-99d9-5ed1da374aff.socket"
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="Got mpv error, retrying..." error="mpv error: property unavailable" retries=1
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="Checking if track is playing" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-c9960aaf-d9c4-4e21-99d9-5ed1da374aff.socket"
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=DietPi/EcCLcxkngL-000209 status=OK
Sep 12 21:47:27 DietPi navidrome[519]: time="2024-09-12T21:47:27+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/jukeboxControl.view?u=prupert&s=7a7kijec6qc8plkj4jdd8rl658&t=5c0b4e312a81e238a3582ed365aeac38&v=1.2.0&c=DSub&action=skip&index=0&offset=0" elapsedTime=855.1ms httpStatus=200 remoteAddr="192.168.1.44:40710" requestId=DietPi/EcCLcxkngL-000209 responseSize=248 userAgent=DSub
Sep 12 21:47:28 DietPi navidrome[519]: time="2024-09-12T21:47:28+01:00" level=info msg="Hitting end-of-stream, signalling on channel"
Sep 12 21:47:28 DietPi navidrome[519]: time="2024-09-12T21:47:28+01:00" level=debug msg="Track switching detected"

pruperting commented 2 months ago

Guess next steps are to turn on debug logging in mpv...

pruperting commented 2 months ago

Struggling to get logs out of mpv, but working through that. I suspect this is linked to the permissions of the user that is calling mpv. The mpv command listed in the log runs fine if I call it directly, but seems to error when navidrome calls it, which I assume is down to the permissions of the user (or the way navidrome is calling the command).

kgarner7 commented 2 months ago

I think I had something similar, check if the user has access to sound/audio group (or something similar). There's a group which should have permissions for audio devices.

pruperting commented 2 months ago

Thanks for replying, the user and the navidrome user both are members of the audio group, so I think that gives them what they need.

Ive got logs out out mpv now and I can't see any issues, other than it clear skips straight to the end of the file, no real evidence of the file being "played":

[   0.029][v][cplayer] mpv 0.35.1 Copyright © 2000-2023 mpv/MPlayer/mplayer2 projects
[   0.033][v][cplayer]  built on UNKNOWN
[   0.033][v][cplayer] FFmpeg library versions:
[   0.033][v][cplayer]    libavutil       57.28.100
[   0.033][v][cplayer]    libavcodec      59.37.100
[   0.033][v][cplayer]    libavformat     59.27.100
[   0.033][v][cplayer]    libswscale      6.7.100
[   0.033][v][cplayer]    libavfilter     8.44.100
[   0.033][v][cplayer]    libswresample   4.7.100
[   0.033][v][cplayer] FFmpeg version: 5.1.6-0+deb12u1
[   0.033][v][cplayer]
[   0.033][v][cplayer] Configuration: meson configure build -Dprefix=/usr -Dbuildtype=plain -Doptimization=plain
[   0.033][v][cplayer] List of enabled features: alsa av-channel-layout caca cdda cplayer cplugins dmabuf-interop-gl dmabuf-interop-pl dmabuf-wayland drm drm-is-kms dvbin dvdnav egl egl-drm egl-helpers egl-x11 ffmpeg gbm gl gl-wayland glibc-thread-name glob glob-posix gpl iconv jack javascript jpeg jpegxl lcms2 libarchive libass libavdevice libbluray libdl libm libmpv-shared libplacebo libplacebo-next librt linux-fstatfs lua52 manpage-build memfd_create noexecstack pipewire plain-gl posix pulse rubberband rubberband-3 sdl2 sdl2-audio sdl2-gamepad sdl2-video sixel spirv-cross stdatomic threads uchardet vaapi vaapi-drm vaapi-egl vaapi-libplacebo vaapi-wayland vaapi-x-egl vaapi-x11 vdpau vector vt.h vulkan wayland wayland_protocols_1_24 x11 xv zimg zlib
[   0.033][d][osc] Loading lua script @osc.lua...
[   0.033][d][ytdl_hook] Loading lua script @ytdl_hook.lua...
[   0.033][d][stats] Loading lua script @stats.lua...
[   0.033][d][console] Loading lua script @console.lua...
[   0.034][d][auto_profiles] Loading lua script @auto_profiles.lua...
[   0.036][d][osc] loading mp.defaults
[   0.036][d][stats] loading mp.defaults
[   0.036][d][ytdl_hook] loading mp.defaults
[   0.036][d][auto_profiles] loading mp.defaults
[   0.036][d][console] loading mp.defaults
[   0.039][d][global] user path: '/tmp/mpv-ctrl-45c49d26-99fc-4d55-a3b2-b0693ffb178c.socket' -> '/tmp/mpv-ctrl-45c49d26-99fc-4d55-a3b2-b0693ffb178c.socket'
[   0.040][d][global] config path: 'scripts' -/-> '/mnt/dietpi_userdata/navidrome/.config/mpv/scripts'
[   0.040][d][global] config path: 'scripts' -/-> '/mnt/dietpi_userdata/navidrome/.mpv/scripts'
[   0.041][d][global] config path: 'scripts' -/-> '/etc/mpv/scripts'
[   0.041][v][cplayer] Waiting for scripts...
[   0.041][v][ipc] Starting IPC master
[   0.042][v][ipc] Listening to IPC socket.
[   0.042][d][auto_profiles] loading @auto_profiles.lua
[   0.042][d][osc] loading @osc.lua
[   0.043][d][console] loading @console.lua
[   0.047][d][ytdl_hook] loading @ytdl_hook.lua
[   0.049][d][stats] loading @stats.lua
[   0.051][d][console] reading options for console
[   0.051][d][global] config path: 'script-opts/console.conf' -/-> '/mnt/dietpi_userdata/navidrome/.config/mpv/script-opts/console.conf'
[   0.051][d][global] config path: 'script-opts/console.conf' -/-> '/mnt/dietpi_userdata/navidrome/.mpv/script-opts/console.conf'
[   0.051][d][global] config path: 'script-opts/console.conf' -/-> '/etc/mpv/script-opts/console.conf'
[   0.051][d][console] script-opts/console.conf not found.
[   0.051][d][global] config path: 'lua-settings/console.conf' -/-> '/mnt/dietpi_userdata/navidrome/.config/mpv/lua-settings/console.conf'
[   0.051][d][global] config path: 'lua-settings/console.conf' -/-> '/mnt/dietpi_userdata/navidrome/.mpv/lua-settings/console.conf'
[   0.051][d][global] config path: 'lua-settings/console.conf' -/-> '/etc/mpv/lua-settings/console.conf'
[   0.051][d][console] lua-settings/console.conf not found.
[   0.053][d][auto_profiles] Exiting...
[   0.058][d][global] config path: 'fonts' -/-> '/mnt/dietpi_userdata/navidrome/.config/mpv/fonts'
[   0.058][d][global] config path: 'fonts' -/-> '/mnt/dietpi_userdata/navidrome/.mpv/fonts'
[   0.058][d][global] config path: 'fonts' -/-> '/etc/mpv/fonts'
[   0.058][d][osd/libass] ASS library version: 0x1701000 (runtime 0x1701000)
[   0.058][v][osd/libass] libass API version: 0x1701000
[   0.058][v][osd/libass] libass source: tarball: 0.17.1
[   0.060][d][ytdl_hook] reading options for ytdl_hook
[   0.060][d][global] config path: 'script-opts/ytdl_hook.conf' -/-> '/mnt/dietpi_userdata/navidrome/.config/mpv/script-opts/ytdl_hook.conf'
[   0.060][d][global] config path: 'script-opts/ytdl_hook.conf' -/-> '/mnt/dietpi_userdata/navidrome/.mpv/script-opts/ytdl_hook.conf'
[   0.060][d][global] config path: 'script-opts/ytdl_hook.conf' -/-> '/etc/mpv/script-opts/ytdl_hook.conf'
[   0.060][d][ytdl_hook] script-opts/ytdl_hook.conf not found.
[   0.060][d][global] config path: 'lua-settings/ytdl_hook.conf' -/-> '/mnt/dietpi_userdata/navidrome/.config/mpv/lua-settings/ytdl_hook.conf'
[   0.060][d][global] config path: 'lua-settings/ytdl_hook.conf' -/-> '/mnt/dietpi_userdata/navidrome/.mpv/lua-settings/ytdl_hook.conf'
[   0.060][d][global] config path: 'lua-settings/ytdl_hook.conf' -/-> '/etc/mpv/lua-settings/ytdl_hook.conf'
[   0.060][d][ytdl_hook] lua-settings/ytdl_hook.conf not found.
[   0.063][v][osd/libass] Shaper: FriBidi 1.0.8 (SIMPLE) HarfBuzz-ng 6.0.0 (COMPLEX)
[   0.063][d][global] config path: 'subfont.ttf' -/-> '/mnt/dietpi_userdata/navidrome/.config/mpv/subfont.ttf'
[   0.063][d][global] config path: 'subfont.ttf' -/-> '/mnt/dietpi_userdata/navidrome/.mpv/subfont.ttf'
[   0.063][d][global] config path: 'subfont.ttf' -/-> '/etc/mpv/subfont.ttf'
[   0.063][d][global] config path: 'fonts.conf' -/-> '/mnt/dietpi_userdata/navidrome/.config/mpv/fonts.conf'
[   0.063][d][global] config path: 'fonts.conf' -/-> '/mnt/dietpi_userdata/navidrome/.mpv/fonts.conf'
[   0.063][d][global] config path: 'fonts.conf' -/-> '/etc/mpv/fonts.conf'
[   0.063][v][osd/libass] Setting up fonts...
[   0.065][d][osc] reading options for osc
[   0.066][d][global] config path: 'script-opts/osc.conf' -/-> '/mnt/dietpi_userdata/navidrome/.config/mpv/script-opts/osc.conf'
[   0.066][d][global] config path: 'script-opts/osc.conf' -/-> '/mnt/dietpi_userdata/navidrome/.mpv/script-opts/osc.conf'
[   0.066][d][global] config path: 'script-opts/osc.conf' -/-> '/etc/mpv/script-opts/osc.conf'
[   0.066][d][osc] script-opts/osc.conf not found.
[   0.066][d][global] config path: 'lua-settings/osc.conf' -/-> '/mnt/dietpi_userdata/navidrome/.config/mpv/lua-settings/osc.conf'
[   0.066][d][global] config path: 'lua-settings/osc.conf' -/-> '/mnt/dietpi_userdata/navidrome/.mpv/lua-settings/osc.conf'
[   0.066][d][global] config path: 'lua-settings/osc.conf' -/-> '/etc/mpv/lua-settings/osc.conf'
[   0.066][d][osc] lua-settings/osc.conf not found.
[   0.068][d][stats] reading options for stats
[   0.068][d][global] config path: 'script-opts/stats.conf' -/-> '/mnt/dietpi_userdata/navidrome/.config/mpv/script-opts/stats.conf'
[   0.069][d][global] config path: 'script-opts/stats.conf' -/-> '/mnt/dietpi_userdata/navidrome/.mpv/script-opts/stats.conf'
[   0.069][d][global] config path: 'script-opts/stats.conf' -/-> '/etc/mpv/script-opts/stats.conf'
[   0.069][d][stats] script-opts/stats.conf not found.
[   0.069][d][global] config path: 'lua-settings/stats.conf' -/-> '/mnt/dietpi_userdata/navidrome/.config/mpv/lua-settings/stats.conf'
[   0.069][d][global] config path: 'lua-settings/stats.conf' -/-> '/mnt/dietpi_userdata/navidrome/.mpv/lua-settings/stats.conf'
[   0.070][d][global] config path: 'lua-settings/stats.conf' -/-> '/etc/mpv/lua-settings/stats.conf'
[   0.070][d][stats] lua-settings/stats.conf not found.
[   0.070][v][ipc_0] Client connected
[   0.091][v][osd/libass] Using font provider fontconfig
[   0.091][v][osd/libass] Done.
[   0.094][v][cplayer] Set property: volume=100 -> 1
[   0.101][v][cplayer] Set property: pause=false -> 1
[   0.101][d][cplayer] Run command: define-section, flags=64, args=[name="input_console", contents="", flags="default"]
[   0.102][d][cplayer] Run command: enable-section, flags=64, args=[name="input_console", flags="allow-hide-cursor+allow-vo-dragging"]
[   0.102][d][cplayer] Run command: define-section, flags=64, args=[name="input_forced_console", contents="", flags="force"]
[   0.102][d][cplayer] Run command: enable-section, flags=64, args=[name="input_forced_console", flags="allow-hide-cursor+allow-vo-dragging"]
[   0.104][d][cplayer] Run command: define-section, flags=64, args=[name="showhide", contents="mouse_move script-binding osc/__keybinding1\nmouse_leave script-binding osc/__keybinding2\n", flags="force"]
[   0.104][d][cplayer] Run command: define-section, flags=64, args=[name="showhide_wc", contents="mouse_move script-binding osc/__keybinding3\nmouse_leave script-binding osc/__keybinding4\n", flags="force"]
[   0.105][d][cplayer] Run command: enable-section, flags=64, args=[name="showhide", flags="allow-hide-cursor+allow-vo-dragging"]
[   0.105][d][cplayer] Run command: enable-section, flags=64, args=[name="showhide_wc", flags="allow-hide-cursor+allow-vo-dragging"]
[   0.105][d][cplayer] Run command: define-section, flags=64, args=[name="input", contents="mbtn_left script-binding osc/__keybinding5\nshift+mbtn_left script-binding osc/__keybinding6\nmbtn_right script-binding osc/__keybinding7\nmbtn_mid script-binding osc/__keybinding8\nwheel_up script-binding osc/__keybinding9\nwheel_down script-binding osc/__keybinding10\nmbtn_left_dbl ignore\nshift+mbtn_left_dbl ignore\nmbtn_right_dbl ignore\n", flags="force"]
[   0.106][d][cplayer] Run command: enable-section, flags=64, args=[name="input", flags=""]
[   0.106][d][cplayer] Run command: define-section, flags=64, args=[name="window-controls", contents="mbtn_left script-binding osc/__keybinding11\n", flags="force"]
[   0.106][d][cplayer] Run command: enable-section, flags=64, args=[name="window-controls", flags=""]
[   0.106][d][cplayer] Run command: change-list, flags=64, args=[name="shared-script-properties", operation="append", value="osc-visibility=auto"]
[   0.106][v][cplayer] Set property: shared-script-properties -> 1
[   0.106][d][cplayer] Run command: disable-section, flags=64, args=[name="input"]
[   0.107][d][cplayer] Run command: disable-section, flags=64, args=[name="window-controls"]
[   0.107][d][cplayer] Run command: change-list, flags=64, args=[name="shared-script-properties", operation="append", value="osc-margins=0.000000,0.000000,0.000000,0.000000"]
[   0.108][v][cplayer] Set property: shared-script-properties -> 1
[   0.108][d][cplayer] Run command: define-section, flags=64, args=[name="input_stats", contents="", flags="default"]
[   0.108][d][cplayer] Run command: enable-section, flags=64, args=[name="input_stats", flags="allow-hide-cursor+allow-vo-dragging"]
[   0.108][d][cplayer] Run command: define-section, flags=64, args=[name="input_forced_stats", contents="", flags="force"]
[   0.109][d][cplayer] Run command: enable-section, flags=64, args=[name="input_forced_stats", flags="allow-hide-cursor+allow-vo-dragging"]
[   0.109][v][cplayer] Done loading scripts.
[   0.109][d][global] config path: 'watch_later' -> '/mnt/dietpi_userdata/navidrome/.config/mpv/watch_later'
[   0.110][v][cplayer] Running hook: ytdl_hook/on_load
[   0.111][v][ytdl_hook] ytdl:// hook
[   0.111][v][ytdl_hook] not a ytdl:// url
[   0.111][d][cplayer] Run command: change-list, flags=64, args=[name="shared-script-properties", operation="append", value="osc-margins=0.000000,0.000000,0.000000,0.000000"]
[   0.111][v][cplayer] Set property: shared-script-properties -> 1
[   0.112][v][ifo_dvdnav] Opening /mnt/sda/FLAC/Techno/90s/Reactivate 12/1-03-Pablo Gargano-Everyone's Future.flac
[   0.112][d][osc] osc_init
[   0.112][v][bdmv/bluray] Opening /mnt/sda/FLAC/Techno/90s/Reactivate 12/1-03-Pablo Gargano-Everyone's Future.flac
[   0.112][v][file] Opening /mnt/sda/FLAC/Techno/90s/Reactivate 12/1-03-Pablo Gargano-Everyone's Future.flac
[   0.112][d][file] resize stream to 131072 bytes, drop 0 bytes
[   0.113][d][file] Stream opened successfully.
[   0.113][v][demux] Trying demuxers for level=normal.
[   0.113][d][demux] Trying demuxer: disc (force-level: normal)
[   0.113][d][demux] Trying demuxer: edl (force-level: normal)
[   0.115][d][cplayer] Run command: change-list, flags=64, args=[name="shared-script-properties", operation="append", value="osc-margins=0.000000,0.000000,0.000000,0.000000"]
[   0.115][v][cplayer] Set property: shared-script-properties -> 1
[   0.116][d][global] config path: 'fonts' -/-> '/mnt/dietpi_userdata/navidrome/.config/mpv/fonts'
[   0.116][d][global] config path: 'fonts' -/-> '/mnt/dietpi_userdata/navidrome/.mpv/fonts'
[   0.116][d][demux] Trying demuxer: cue (force-level: normal)
[   0.116][d][global] config path: 'fonts' -/-> '/etc/mpv/fonts'
[   0.117][d][osd/libass] ASS library version: 0x1701000 (runtime 0x1701000)
[   0.117][d][demux] Trying demuxer: rawaudio (force-level: normal)
[   0.117][d][demux] Trying demuxer: rawvideo (force-level: normal)
[   0.117][v][osd/libass] libass API version: 0x1701000
[   0.117][v][osd/libass] libass source: tarball: 0.17.1
[   0.117][d][demux] Trying demuxer: mkv (force-level: normal)
[   0.117][d][demux] Trying demuxer: libarchive (force-level: normal)
[   0.119][v][osd/libass] Shaper: FriBidi 1.0.8 (SIMPLE) HarfBuzz-ng 6.0.0 (COMPLEX)
[   0.119][d][global] config path: 'subfont.ttf' -/-> '/mnt/dietpi_userdata/navidrome/.config/mpv/subfont.ttf'
[   0.119][d][global] config path: 'subfont.ttf' -/-> '/mnt/dietpi_userdata/navidrome/.mpv/subfont.ttf'
[   0.119][d][global] config path: 'subfont.ttf' -/-> '/etc/mpv/subfont.ttf'
[   0.119][d][global] config path: 'fonts.conf' -/-> '/mnt/dietpi_userdata/navidrome/.config/mpv/fonts.conf'
[   0.119][d][global] config path: 'fonts.conf' -/-> '/mnt/dietpi_userdata/navidrome/.mpv/fonts.conf'
[   0.119][d][global] config path: 'fonts.conf' -/-> '/etc/mpv/fonts.conf'
[   0.119][v][osd/libass] Setting up fonts...
[   0.120][d][demux] Trying demuxer: lavf (force-level: normal)
[   0.145][v][osd/libass] Using font provider fontconfig
[   0.145][v][osd/libass] Done.
[   0.147][d][cplayer] Run command: define-section, flags=64, args=[name="input_osc", contents="", flags="default"]
[   0.147][d][cplayer] Run command: enable-section, flags=64, args=[name="input_osc", flags="allow-hide-cursor+allow-vo-dragging"]
[   0.147][d][cplayer] Run command: define-section, flags=64, args=[name="input_forced_osc", contents="", flags="force"]
[   0.147][d][cplayer] Run command: enable-section, flags=64, args=[name="input_forced_osc", flags="allow-hide-cursor+allow-vo-dragging"]
[   0.149][v][lavf] Found 'flac' at score=100 size=2048.
[   0.157][v][lavf] avformat_find_stream_info() finished after 229376 bytes.
[   0.157][v][lavf] Assuming this is an image format.
[   0.158][v][demux] Detected file format: flac (libavformat)
[   0.158][v][cplayer] Opening done: /mnt/sda/FLAC/Techno/90s/Reactivate 12/1-03-Pablo Gargano-Everyone's Future.flac
[   0.159][v][find_files] Loading external files in /mnt/sda/FLAC/Techno/90s/Reactivate 12/
[   0.159][d][global] config path: 'sub' -/-> '/mnt/dietpi_userdata/navidrome/.config/mpv/sub'
[   0.159][d][global] config path: 'sub' -/-> '/mnt/dietpi_userdata/navidrome/.mpv/sub'
[   0.159][d][global] config path: 'sub' -/-> '/etc/mpv/sub'
[   0.159][v][ifo_dvdnav] Opening /mnt/sda/FLAC/Techno/90s/Reactivate 12/folder.jpg
[   0.160][v][bdmv/bluray] Opening /mnt/sda/FLAC/Techno/90s/Reactivate 12/folder.jpg
[   0.160][v][file] Opening /mnt/sda/FLAC/Techno/90s/Reactivate 12/folder.jpg
[   0.160][d][file] resize stream to 131072 bytes, drop 0 bytes
[   0.160][d][file] Stream opened successfully.
[   0.160][v][demux] Trying demuxers for level=normal.
[   0.160][d][demux] Trying demuxer: disc (force-level: normal)
[   0.160][d][demux] Trying demuxer: edl (force-level: normal)
[   0.160][d][demux] Trying demuxer: cue (force-level: normal)
[   0.160][d][demux] Trying demuxer: rawaudio (force-level: normal)
[   0.160][d][demux] Trying demuxer: rawvideo (force-level: normal)
[   0.160][d][demux] Trying demuxer: mkv (force-level: normal)
[   0.160][d][demux] Trying demuxer: libarchive (force-level: normal)
[   0.161][d][demux] Trying demuxer: lavf (force-level: normal)
[   0.177][d][osc] osc_init
[   0.179][d][cplayer] Run command: change-list, flags=64, args=[name="shared-script-properties", operation="append", value="osc-margins=0.000000,0.000000,0.000000,0.000000"]
[   0.179][v][cplayer] Set property: shared-script-properties -> 1
[   0.179][v][lavf] Found 'jpeg_pipe' at score=26 size=2048.
[   0.184][v][lavf] avformat_find_stream_info() finished after 158239 bytes.
[   0.184][v][lavf] Assuming this is an image format.
[   0.184][v][demux] Detected file format: jpeg_pipe (libavformat)
[   0.185][v][cplayer] Running hook: ytdl_hook/on_preloaded
[   0.185][v][lavf] select track 0
[   0.185][i][cplayer]      Video --vid=1 [P] (mjpeg 500x494 1.000fps)
[   0.185][i][cplayer]      Video --vid=2 [P] 'folder.jpg' (mjpeg 943x924 1.000fps) (external)
[   0.185][i][cplayer]  (+) Audio --aid=1 (flac 2ch 44100Hz)
[   0.186][i][display-tags] File tags:
[   0.186][i][display-tags]  Artist: Pablo Gargano
[   0.186][i][display-tags]  Album: Reactivate 12
[   0.186][i][display-tags]  Album_Artist: Reactivate
[   0.186][i][display-tags]  Date: 1997
[   0.186][i][display-tags]  Genre: Techno
[   0.186][i][display-tags]  Title: Everyone's Future
[   0.186][i][display-tags]  Track: 3
[   0.188][v][ad] Codec list:
[   0.188][v][ad]     flac - FLAC (Free Lossless Audio Codec)
[   0.188][v][ad] Opening decoder flac
[   0.193][v][ad] Requesting 1 threads for decoding.
[   0.193][v][ad] Selected codec: flac (FLAC (Free Lossless Audio Codec))
[   0.193][v][af] User filter list:
[   0.193][v][af]   (empty)
[   0.193][v][cplayer] Starting playback...
[   0.197][v][af] [in] 44100Hz stereo 2ch s16
[   0.197][v][af] [userspeed] 44100Hz stereo 2ch s16
[   0.197][v][af] [userspeed] (disabled)
[   0.197][v][af] [convert] 44100Hz stereo 2ch s16
[   0.197][v][ao] Trying audio driver 'pcm'
[   0.198][v][ao/pcm] requested format: 48000 Hz, stereo channels, s16
[   0.198][v][ao/pcm] Channel layouts:
[   0.198][v][ao/pcm]  - waveext
[   0.198][v][ao/pcm] result: stereo
[   0.198][i][ao/pcm] File: /tmp/mpd (WAVE)
[   0.198][i][ao/pcm] PCM: Samplerate: 48000 Hz Channels: 2 Format: s16
[   0.273][v][ao/pcm] device buffer: 65536 samples.
[   0.273][v][ao/pcm] using soft-buffer of 65536 samples.
[   0.274][i][cplayer] AO: [pcm] 48000Hz stereo 2ch s16
[   0.274][v][cplayer] AO: Description: RAW PCM/WAVE file writer audio output
[   0.274][v][autoconvert] inserting resampler
[   0.274][v][swresample] format change, reinitializing resampler
[   0.274][v][swresample] 44100Hz stereo s16 -> 48000Hz stereo s16
[   0.277][v][af] [out] 48000Hz stereo 2ch s16
[   0.294][d][osc] osc_init
[   0.294][v][cplayer] audio ready
[   0.294][v][cplayer] starting audio playback
[   0.294][v][cplayer] playback restart complete @ -0.000000, audio=playing, video=eof
[   0.300][v][ao/pcm] starting AO
[   0.465][d][cplayer] Run command: change-list, flags=64, args=[name="shared-script-properties", operation="append", value="osc-margins=0.000000,0.000000,0.000000,0.000000"]
[   0.465][v][cplayer] Set property: shared-script-properties -> 1
[   0.667][v][cplayer] Set property: pause=true -> 1
[   2.858][v][cplayer] Set property: pause=true -> 1
[   6.892][v][cplayer] Set property: pause=true -> 1
[   6.897][d][cplayer] Run command: quit, flags=64, args=[code="0"]
[   6.898][v][cplayer] EOF code: 5
[   6.898][d][ad] Uninit decoder.
[   6.901][d][cplayer] Terminating demuxers...
[   6.905][d][cplayer] Done terminating demuxers.
[   6.911][v][cplayer] finished playback, success (reason 3)
[   6.911][i][cplayer]

kgarner7 commented 2 months ago

I see. I can't say much about MPD. Can you try with just the standard template first and see if that behaves? If that does, try to check if the pcm file is accessible via your Navidrome user.

pruperting commented 2 months ago

/tmp/mpd is just the name of the pcm file snapserver is using so shouldn't make a difference. But I'll default to the standard template and share back.

pruperting commented 2 months ago

So, just tried a fresh install on an Ubuntu device. Exactly the same issue, mpv doesn't work in jukebox mode - though calling the mpv command directly using the command in the log, does work (providing I quote the file location).

Logs:

Sep 17 22:46:56 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:46:56+01:00" level=debug msg="Loading track" mediaType=audio/flac trackPath="/home/prupert/Music/Yogo Yogo/03-Ingani.flac"
Sep 17 22:46:56 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:46:56+01:00" level=debug msg="Executing mpv command" cmd="[/usr/bin/mpv --audio-device=auto --no-audio-display --pause /home/prupert/Music/Yogo Yogo/03-Ingani.flac --input-ipc-server=/tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket]"
Sep 17 22:46:56 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:46:56+01:00" level=debug msg="HTTP: GET http://192.168.1.34:4533/rest/jukeboxControl.view?u=admin&s=[REDACTED]&t=[REDACTED]&v=1.2.0&c=DSub&action=skip&index=0&offset=0" elapsedTime=212.6ms httpStatus=200 remoteAddr="192.168.1.44:46774" requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000014 responseSize=248 userAgent=DSub
Sep 17 22:46:56 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:46:56+01:00" level=debug msg="Socket found" retries=1 waitTime=100.5ms
Sep 17 22:46:56 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:46:56+01:00" level=debug msg="Setting volume" track="Name: /home/prupert/Music/Yogo Yogo/03-Ingani.flac, Socket: /tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket" volume=1
Sep 17 22:46:56 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:46:56+01:00" level=debug msg="API: New request /rest/scrobble.view" client=DSub requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000016 username=admin version=1.2.0
Sep 17 22:46:56 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:46:56+01:00" level=debug msg="Scrobbling tracks" ids="[b56679cc6b2165e9e8ca6d01abc280a1]" requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000016 times="[]"
Sep 17 22:46:56 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:46:56+01:00" level=info msg=Scrobbled artist="Penny Penny" requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000016 timestamp="2024-09-17 22:46:56.640321767 +0100 BST m=+230.080317890" title="Ibola Aids" user=admin
Sep 17 22:46:56 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:46:56+01:00" level=debug msg="API: Successful response" endpoint=/rest/scrobble.view requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000016 status=OK
Sep 17 22:46:56 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:46:56+01:00" level=debug msg="HTTP: GET http://192.168.1.34:4533/rest/scrobble.view?u=admin&s=[REDACTED]&t=[REDACTED]&v=1.2.0&c=DSub&id=b56679cc6b2165e9e8ca6d01abc280a1&submission=true" elapsedTime=4.7ms httpStatus=200 remoteAddr="192.168.1.44:46774" requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000016 responseSize=175 userAgent=DSub
Sep 17 22:46:56 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:46:56+01:00" level=error msg="SQL: `SELECT coalesce(starred, 0) as starred, coalesce(rating, 0) as rating, starred_at, play_date, coalesce(play_count, 0) as play_count, album.* FROM album LEFT JOIN annotation on (annotation.item_id = album.id AND annotation.item_type = 'album' AND annotation.user_id = '5e5ff689-0f36-4533-87f3-38ba2cae1fb8') WHERE (.id = {:p0})`" args="map[p0:950186c576b99d81daace6b1c9f7df8d]" elapsedTime="119.931µs" error="near \".\": syntax error" requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000017 rowsAffected=0 username=admin
Sep 17 22:46:56 prupert-OptiPlex-3060 navidrome[31888]: 2024/09/17 22:46:56 Error reading album: near ".": syntax error
Sep 17 22:46:56 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:46:56+01:00" level=error msg="SQL: `SELECT count(distinct album.id) as count FROM album LEFT JOIN annotation on (annotation.item_id = album.id AND annotation.item_type = 'album' AND annotation.user_id = '5e5ff689-0f36-4533-87f3-38ba2cae1fb8') LEFT JOIN album_genres ag on album.id = ag.album_id LEFT JOIN genre on ag.genre_id = genre.id WHERE (.id = {:p0})`" args="map[p0:950186c576b99d81daace6b1c9f7df8d]" elapsedTime="162.185µs" error="near \".\": syntax error" requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000017 rowsAffected=1 username=admin
Sep 17 22:46:56 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:46:56+01:00" level=error msg="HTTP: GET http://192.168.1.34:4533/api/album?id=950186c576b99d81daace6b1c9f7df8d" elapsedTime=2.6ms httpStatus=500 remoteAddr="192.168.1.34:42394" requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000017 responseSize=40 userAgent="Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/125.0.0.0 Safari/537.36"
Sep 17 22:46:56 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:46:56+01:00" level=debug msg="Unpausing track" track="Name: /home/prupert/Music/Yogo Yogo/03-Ingani.flac, Socket: /tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket"
Sep 17 22:46:56 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:46:56+01:00" level=info msg="Hitting end-of-stream, signalling on channel"
Sep 17 22:47:00 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:00+01:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000018 username=admin version=1.2.0
Sep 17 22:47:00 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:00+01:00" level=debug msg="Processing GetDevice" user=admin
Sep 17 22:47:00 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:00+01:00" level=info msg="JukeboxControl request received" action=start requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000018
Sep 17 22:47:00 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:00+01:00" level=debug msg="Processing Start action" device="Name: auto, Gain: 1.0000, Loaded track: Name: /home/prupert/Music/Yogo Yogo/03-Ingani.flac, Socket: /tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket" requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000018
Sep 17 22:47:00 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:00+01:00" level=debug msg="Checking if track is playing" track="Name: /home/prupert/Music/Yogo Yogo/03-Ingani.flac, Socket: /tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket"
Sep 17 22:47:00 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:00+01:00" level=error msg="Problem getting paused status" error="trying to send command on closed mpv client" track="Name: /home/prupert/Music/Yogo Yogo/03-Ingani.flac, Socket: /tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket"
Sep 17 22:47:00 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:00+01:00" level=debug msg="Unpausing track" track="Name: /home/prupert/Music/Yogo Yogo/03-Ingani.flac, Socket: /tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket"
Sep 17 22:47:00 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:00+01:00" level=error msg="Error unpausing track" error="trying to send command on closed mpv client" track="Name: /home/prupert/Music/Yogo Yogo/03-Ingani.flac, Socket: /tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket"
Sep 17 22:47:00 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:00+01:00" level=error msg="Error getting position in track" error="trying to send command on closed mpv client" track="Name: /home/prupert/Music/Yogo Yogo/03-Ingani.flac, Socket: /tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket"
Sep 17 22:47:00 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:00+01:00" level=debug msg="Checking if track is playing" track="Name: /home/prupert/Music/Yogo Yogo/03-Ingani.flac, Socket: /tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket"
Sep 17 22:47:00 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:00+01:00" level=error msg="Problem getting paused status" error="trying to send command on closed mpv client" track="Name: /home/prupert/Music/Yogo Yogo/03-Ingani.flac, Socket: /tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket"
Sep 17 22:47:00 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:00+01:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000018 status=OK
Sep 17 22:47:00 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:00+01:00" level=debug msg="HTTP: GET http://192.168.1.34:4533/rest/jukeboxControl.view?u=admin&s=[REDACTED]&t=[REDACTED]&v=1.2.0&c=DSub&action=start" elapsedTime=3.4ms httpStatus=200 remoteAddr="192.168.1.44:46774" requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000018 responseSize=248 userAgent=DSub
Sep 17 22:47:01 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:01+01:00" level=debug msg="API: New request /rest/scrobble.view" client=DSub requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000019 username=admin version=1.2.0
Sep 17 22:47:01 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:01+01:00" level=info msg="Now Playing" artist="Penny Penny" player="DSub [DSub]" requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000019 title=Ingani user=admin
Sep 17 22:47:01 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:01+01:00" level=debug msg="API: Successful response" endpoint=/rest/scrobble.view requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000019 status=OK
Sep 17 22:47:01 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:01+01:00" level=debug msg="HTTP: GET http://192.168.1.34:4533/rest/scrobble.view?u=admin&s=[REDACTED]&t=[REDACTED]&v=1.2.0&c=DSub&id=1672dfccd93cc5174262c28ec501a729&submission=false" elapsedTime=5.5ms httpStatus=200 remoteAddr="192.168.1.44:46774" requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000019 responseSize=175 userAgent=DSub
Sep 17 22:47:05 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:05+01:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000020 username=admin version=1.2.0
Sep 17 22:47:05 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:05+01:00" level=debug msg="Processing GetDevice" user=admin
Sep 17 22:47:05 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:05+01:00" level=info msg="JukeboxControl request received" action=status requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000020
Sep 17 22:47:05 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:05+01:00" level=debug msg="processing Status action on: Name: auto, Gain: 1.0000, Loaded track: Name: /home/prupert/Music/Yogo Yogo/03-Ingani.flac, Socket: /tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket, queue: #Items: 8, idx: 1, files: 0:/home/prupert/Music/Yogo Yogo/02-Ibola Aids.flac 1:/home/prupert/Music/Yogo Yogo/03-Ingani.flac 2:/home/prupert/Music/Yogo Yogo/04-Amarumasi.flac 3:/home/prupert/Music/Yogo Yogo/05-Kulani Kulani.flac 4:/home/prupert/Music/Yogo Yogo/06-Hai Kamina.flac 5:/home/prupert/Music/Yogo Yogo/07-Yogo Yogo.flac 6:/home/prupert/Music/Yogo Yogo/08-Ti Samboko.flac 7:/home/prupert/Music/Yogo Yogo/09-Ama Owners.flac " requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000020
Sep 17 22:47:05 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:05+01:00" level=error msg="Error getting position in track" error="trying to send command on closed mpv client" track="Name: /home/prupert/Music/Yogo Yogo/03-Ingani.flac, Socket: /tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket"
Sep 17 22:47:05 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:05+01:00" level=debug msg="Checking if track is playing" track="Name: /home/prupert/Music/Yogo Yogo/03-Ingani.flac, Socket: /tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket"
Sep 17 22:47:05 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:05+01:00" level=error msg="Problem getting paused status" error="trying to send command on closed mpv client" track="Name: /home/prupert/Music/Yogo Yogo/03-Ingani.flac, Socket: /tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket"
Sep 17 22:47:05 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:05+01:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000020 status=OK
Sep 17 22:47:05 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:05+01:00" level=debug msg="HTTP: GET http://192.168.1.34:4533/rest/jukeboxControl.view?u=admin&s=[REDACTED]&t=[REDACTED]&v=1.2.0&c=DSub&action=status" elapsedTime=2.8ms httpStatus=200 remoteAddr="192.168.1.44:46774" requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000020 responseSize=248 userAgent=DSub
Sep 17 22:47:06 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:06+01:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000021 username=admin version=1.2.0
Sep 17 22:47:06 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:06+01:00" level=debug msg="Processing GetDevice" user=admin
Sep 17 22:47:06 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:06+01:00" level=info msg="JukeboxControl request received" action=skip requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000021
Sep 17 22:47:06 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:06+01:00" level=debug msg="Processing Skip action" device="Name: auto, Gain: 1.0000, Loaded track: Name: /home/prupert/Music/Yogo Yogo/03-Ingani.flac, Socket: /tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket" index=0 offset=0 requestId=prupert-OptiPlex-3060/fA5QnQ43dt-000021
Sep 17 22:47:06 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:06+01:00" level=debug msg="Checking if track is playing" track="Name: /home/prupert/Music/Yogo Yogo/03-Ingani.flac, Socket: /tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket"
Sep 17 22:47:06 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:06+01:00" level=error msg="Problem getting paused status" error="trying to send command on closed mpv client" track="Name: /home/prupert/Music/Yogo Yogo/03-Ingani.flac, Socket: /tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket"
Sep 17 22:47:06 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:06+01:00" level=debug msg="Closing resources" track="Name: /home/prupert/Music/Yogo Yogo/03-Ingani.flac, Socket: /tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket"
Sep 17 22:47:06 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:06+01:00" level=debug msg="sending shutdown command"
Sep 17 22:47:06 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:06+01:00" level=warning msg="Error sending quit command to mpv-ipc socket" error="trying to send command on closed mpv client"
Sep 17 22:47:06 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:06+01:00" level=debug msg="cancelling executor"
Sep 17 22:47:06 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:06+01:00" level=warning msg="Error canceling executor" error="os: process already finished"
Sep 17 22:47:06 prupert-OptiPlex-3060 navidrome[31888]: time="2024-09-17T22:47:06+01:00" level=debug msg="Removing socketfile" socketfile=/tmp/mpv-ctrl-e8769a0b-e889-4c2b-a46e-98779039d9d0.socket

pruperting commented 2 months ago

Finally, I have tried the docker image and that also fails, though I suspect I need to ensure that mpv is installed as part of that docker image (which I can only assume it is).

It is at this point I throw my hands up in despair as I've got no closer to a solution!

deluan commented 2 months ago

@pruperting Just to be sure: Did you remove the MPVPath from your config as well? You should have these lines in the beginning of your logs:

    MPVPath:                         "",
    MPVCmdTemplate:                  "mpv --audio-device=%d --no-audio-display --pause %f --input-ipc-server=%s",

Can you confirm?

Hey @ms140569, can you take a look whenever you have time? I don't see any issues based on the logs....

crug80 commented 2 months ago

I report similar problems here:

navidrome[929]: time="2024-09-08T14:29:57+02:00" level=debug msg="Processing GetDevice" user=claudio
navidrome[929]: time="2024-09-08T14:29:57+02:00" level=info msg="JukeboxControl request received" action=start requestId=CRH-SRV-00/0UZmCUhACt-000061
navidrome[929]: time="2024-09-08T14:29:57+02:00" level=debug msg="Processing Start action" device="Name: auto, Gain: 1.0000, Loaded track: %!s(<nil>)" requestId=CRH-SRV-00/0UZmCUhACt-000061
navidrome[929]: time="2024-09-08T14:29:57+02:00" level=debug msg="Loading track" mediaType=audio/mpeg trackPath="/media/shareMusic/Abba/Abba/Abba - Abba - 01 - Mamma Mia.mp3"
navidrome[929]: time="2024-09-08T14:29:57+02:00" level=debug msg="Executing mpv command" cmd="[/usr/bin/mpv --audio-device=auto --no-audio-display --pause /media/shareMusic/Abba/Abba/Abba - Abba - 01 - Mamma Mia.mp3 --input-ipc-server=/tmp/mpv-ctrl-0ee36cd9-e1d7-4f12-8a62-f725fb937720.socket]"
navidrome[929]: time="2024-09-08T14:29:58+02:00" level=debug msg="Socket found" retries=5 waitTime=502.1ms
navidrome[929]: time="2024-09-08T14:29:58+02:00" level=debug msg="Setting volume" track="Name: /media/shareMusic/Abba/Abba/Abba - Abba - 01 - Mamma Mia.mp3, Socket: /tmp/mpv-ctrl-0ee36cd9-e1d7-4f12-8a62-f725fb937720.socket" volume=1
navidrome[929]: time="2024-09-08T14:29:58+02:00" level=debug msg="Unpausing track" track="Name: /media/shareMusic/Abba/Abba/Abba - Abba - 01 - Mamma Mia.mp3, Socket: /tmp/mpv-ctrl-0ee36cd9-e1d7-4f12-8a62-f725fb937720.socket"
navidrome[929]: time="2024-09-08T14:29:58+02:00" level=debug msg="Got mpv error, retrying..." error="mpv error: property unavailable" retries=1
navidrome[929]: time="2024-09-08T14:29:58+02:00" level=debug msg="Checking if track is playing" track="Name: /media/shareMusic/Abba/Abba/Abba - Abba - 01 - Mamma Mia.mp3, Socket: /tmp/mpv-ctrl-0ee36cd9-e1d7-4f12-8a62-f725fb937720.socket"
navidrome[929]: time="2024-09-08T14:29:58+02:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=CRH-SRV-00/0UZmCUhACt-000061 status=OK
navidrome[929]: time="2024-09-08T14:29:58+02:00" level=debug msg="HTTP: GET http://192.168.1.18:4533/rest/jukeboxControl.view?action=start&u=claudio&c=Ultrasonic&f=json&v=1.16.0&t=[REDACTED]&s=[REDACTED]" elapsedTime=511ms httpStatus=200 remoteAddr="192.168.1.100:59062" requestId=CRH-SRV-00/0UZmCUhACt-000061 responseSize=203 userAgent=okhttp/4.11.0
navidrome[929]: time="2024-09-08T14:29:58+02:00" level=info msg="Hitting end-of-stream, signalling on channel"
navidrome[929]: time="2024-09-08T14:29:58+02:00" level=debug msg="Track switching detected"
navidrome[929]: time="2024-09-08T14:29:58+02:00" level=debug msg="Closing resources" track="Name: /media/shareMusic/Abba/Abba/Abba - Abba - 01 - Mamma Mia.mp3, Socket: /tmp/mpv-ctrl-0ee36cd9-e1d7-4f12-8a62-f725fb937720.socket"
navidrome[929]: time="2024-09-08T14:29:58+02:00" level=debug msg="sending shutdown command"
navidrome[929]: time="2024-09-08T14:29:58+02:00" level=warning msg="Error sending quit command to mpv-ipc socket" error="trying to send command on closed mpv client"
navidrome[929]: time="2024-09-08T14:29:58+02:00" level=debug msg="cancelling executor"
navidrome[929]: time="2024-09-08T14:29:58+02:00" level=debug msg="Removing socketfile" socketfile=/tmp/mpv-ctrl-0ee36cd9-e1d7-4f12-8a62-f725fb937720.socket
navidrome[929]: time="2024-09-08T14:29:58+02:00" level=debug msg="There is no song left in the playlist. Finish."

Configuration: Rapseberry Pi 4 with RaspiOs (bookworm) Navidrome 0.52.5

ms140569 commented 2 months ago

I'll look into it!

pruperting commented 2 months ago

@pruperting Just to be sure: Did you remove the MPVPath from your config as well? You should have these lines in the beginning of your logs:
    MPVPath:                         "",
    MPVCmdTemplate:                  "mpv --audio-device=%d --no-audio-display --pause %f --input-ipc-server=%s",
Can you confirm?

Hey @ms140569, can you take a look whenever you have time? I don't see any issues based on the logs....

Will check tonight and try with those lines. Thanks for replying and awesome work BTW, navidrome is great.

pruperting commented 2 months ago

Yup, have those:

Sep 18 21:37:55 hc2audioserver navidrome[18486]:     MPVPath:                      "/usr/bin/mpv",
Sep 18 21:37:55 hc2audioserver navidrome[18486]:     MPVCmdTemplate:               "mpv --no-audio-display --pause %f --input-ipc-server=%s --audio-channels=stereo --audio-samplerate=48000 --audio-format=s16 --ao=pcm --ao-pcm-file=/tmp/mpd",

Other relevant bits from the logs:

Sep 18 21:37:55 hc2audioserver navidrome[18486]:     Jukebox:                      conf.jukeboxOptions{
Sep 18 21:37:55 hc2audioserver navidrome[18486]:         Enabled: true,
Sep 18 21:37:55 hc2audioserver navidrome[18486]:         Devices: {
Sep 18 21:37:55 hc2audioserver navidrome[18486]:             {"internal", "alsa/plughw:CARD=ODROIDXU4,DEV=0"},
Sep 18 21:37:55 hc2audioserver navidrome[18486]:         },
Sep 18 21:37:55 hc2audioserver navidrome[18486]:         Default:   "internal",
Sep 18 21:37:55 hc2audioserver navidrome[18486]:         AdminOnly: true,
Sep 18 21:37:55 hc2audioserver navidrome[18486]:     },
snip
Sep 18 21:37:56 hc2audioserver navidrome[18486]: time="2024-09-18T21:37:56+01:00" level=info msg="Starting Jukebox service"
Sep 18 21:37:56 hc2audioserver navidrome[18486]: time="2024-09-18T21:37:56+01:00" level=info msg="1 audio devices found"
Sep 18 21:37:56 hc2audioserver navidrome[18486]: time="2024-09-18T21:37:56+01:00" level=info msg="Using audio device: alsa/plughw:CARD=ODROIDXU4,DEV=0"

pruperting commented 2 months ago

And then a log when trying to play using Dsub Jukebox mode:

Sep 18 21:38:03 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:03+01:00" level=debug msg="API: New request /rest/getUser.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000001 username=prupert version=1.2.0
Sep 18 21:38:03 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:03+01:00" level=debug msg="API: Successful response" endpoint=/rest/getUser.view requestId=hc2audioserver/Rjz9qY1bZV-000001 status=OK
Sep 18 21:38:03 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:03+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/getUser.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&username=prupert" elapsedTime=29.9ms httpStatus=200 remoteAddr="192.168.1.44:40030" requestId=hc2audioserver/Rjz9qY1bZV-000001 responseSize=474 userAgent=DSub
Sep 18 21:38:03 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:03+01:00" level=debug msg="API: New request /rest/savePlayQueue.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000002 username=prupert version=1.2.0
Sep 18 21:38:03 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:03+01:00" level=debug msg="Found matching player" client=DSub id=cc2a618d-96c3-4a61-999e-c00e69c5faee requestId=hc2audioserver/Rjz9qY1bZV-000002 type=DSub username=prupert
Sep 18 21:38:03 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:03+01:00" level=debug msg="API: Successful response" endpoint=/rest/savePlayQueue.view requestId=hc2audioserver/Rjz9qY1bZV-000002 status=OK
Sep 18 21:38:03 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:03+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/savePlayQueue.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&id=c1a9bbacfc087471af313e0b8a2367d1&id=1ada2b3dea7a4acb664b56d5e016c8b9&id=8b44a049895e9fd06ad269edec9f1d84&id=1225df473c3094634638264567e73a07&id=d2519867fc9ab10639ee80e65b729874&current=c1a9bbacfc087471af313e0b8a2367d1&position=0" elapsedTime=11.2ms httpStatus=200 remoteAddr="192.168.1.44:40030" requestId=hc2audioserver/Rjz9qY1bZV-000002 responseSize=175 userAgent=DSub
Sep 18 21:38:06 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:06+01:00" level=debug msg="API: New request /rest/getAlbumList2.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000003 username=prupert version=1.2.0
Sep 18 21:38:06 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:06+01:00" level=debug msg="Found matching player" client=DSub id=cc2a618d-96c3-4a61-999e-c00e69c5faee requestId=hc2audioserver/Rjz9qY1bZV-000003 type=DSub username=prupert
Sep 18 21:38:06 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:06+01:00" level=debug msg="API: Successful response" endpoint=/rest/getAlbumList2.view requestId=hc2audioserver/Rjz9qY1bZV-000003 status=OK
Sep 18 21:38:06 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:06+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/getAlbumList2.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&type=newest&size=20&offset=0" elapsedTime=100.5ms httpStatus=200 remoteAddr="192.168.1.44:40030" requestId=hc2audioserver/Rjz9qY1bZV-000003 responseSize=12409 userAgent=DSub
Sep 18 21:38:08 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:08+01:00" level=debug msg="API: New request /rest/getAlbum.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000004 username=prupert version=1.2.0
Sep 18 21:38:08 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:08+01:00" level=debug msg="Found matching player" client=DSub id=cc2a618d-96c3-4a61-999e-c00e69c5faee requestId=hc2audioserver/Rjz9qY1bZV-000004 type=DSub username=prupert
Sep 18 21:38:08 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:08+01:00" level=debug msg="API: Successful response" endpoint=/rest/getAlbum.view requestId=hc2audioserver/Rjz9qY1bZV-000004 status=OK
Sep 18 21:38:08 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:08+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/getAlbum.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&id=950186c576b99d81daace6b1c9f7df8d" elapsedTime=47.2ms httpStatus=200 remoteAddr="192.168.1.44:40030" requestId=hc2audioserver/Rjz9qY1bZV-000004 responseSize=7577 userAgent=DSub
Sep 18 21:38:12 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:12+01:00" level=debug msg="API: New request /rest/deleteBookmark.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000005 username=prupert version=1.2.0
Sep 18 21:38:12 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:12+01:00" level=debug msg="Found matching player" client=DSub id=cc2a618d-96c3-4a61-999e-c00e69c5faee requestId=hc2audioserver/Rjz9qY1bZV-000005 type=DSub username=prupert
Sep 18 21:38:12 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:12+01:00" level=debug msg="API: Successful response" endpoint=/rest/deleteBookmark.view requestId=hc2audioserver/Rjz9qY1bZV-000005 status=OK
Sep 18 21:38:12 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:12+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/deleteBookmark.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&id=aaf4e847fa4137cebb193f8661f87dd9" elapsedTime=16.1ms httpStatus=200 remoteAddr="192.168.1.44:40030" requestId=hc2audioserver/Rjz9qY1bZV-000005 responseSize=175 userAgent=DSub
Sep 18 21:38:12 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:12+01:00" level=debug msg="API: New request /rest/scrobble.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000006 username=prupert version=1.2.0
Sep 18 21:38:12 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:12+01:00" level=debug msg="Found matching player" client=DSub id=cc2a618d-96c3-4a61-999e-c00e69c5faee requestId=hc2audioserver/Rjz9qY1bZV-000006 type=DSub username=prupert
Sep 18 21:38:12 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:12+01:00" level=info msg="Now Playing" artist="Penny Penny" player="DSub [DSub]" requestId=hc2audioserver/Rjz9qY1bZV-000006 title="Ibola Aids" user=prupert
Sep 18 21:38:12 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:12+01:00" level=debug msg="API: New request /rest/savePlayQueue.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000007 username=prupert version=1.2.0
Sep 18 21:38:12 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:12+01:00" level=debug msg="Sending NowPlaying update" artist="Penny Penny" requestId=hc2audioserver/Rjz9qY1bZV-000006 scrobbler=lastfm track="Ibola Aids"
Sep 18 21:38:12 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:12+01:00" level=debug msg="Found matching player" client=DSub id=cc2a618d-96c3-4a61-999e-c00e69c5faee requestId=hc2audioserver/Rjz9qY1bZV-000007 type=DSub username=prupert
Sep 18 21:38:12 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:12+01:00" level=debug msg="API: Successful response" endpoint=/rest/savePlayQueue.view requestId=hc2audioserver/Rjz9qY1bZV-000007 status=OK
Sep 18 21:38:12 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:12+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/savePlayQueue.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&id=f9aa22fc5662d9f30ba40b117c729047&id=a77204808c96d2739d055a98b26901a3&id=9e32bfe65f74402bda36a1a09012f53d&id=bffc98fb978b8a73eef781bb92a3ed46&id=aaf4e847fa4137cebb193f8661f87dd9&id=54759f620e82720d81e8edb1badf07a5&id=4255c3fc5b1a453e49bbc88d20832fc9&id=9ad15f90a1bf3ebf7d4daba7e2c7ef8c&current=f9aa22fc5662d9f30ba40b117c729047&position=0" elapsedTime=33.3ms httpStatus=200 remoteAddr="192.168.1.44:40032" requestId=hc2audioserver/Rjz9qY1bZV-000007 responseSize=175 userAgent=DSub
Sep 18 21:38:12 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:12+01:00" level=debug msg="Sending NowPlaying update" artist="Penny Penny" requestId=hc2audioserver/Rjz9qY1bZV-000006 scrobbler=listenbrainz track="Ibola Aids"
Sep 18 21:38:13 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:13+01:00" level=debug msg="API: Successful response" endpoint=/rest/scrobble.view requestId=hc2audioserver/Rjz9qY1bZV-000006 status=OK
Sep 18 21:38:13 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:13+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/scrobble.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&id=f9aa22fc5662d9f30ba40b117c729047&submission=false" elapsedTime=809ms httpStatus=200 remoteAddr="192.168.1.44:40030" requestId=hc2audioserver/Rjz9qY1bZV-000006 responseSize=175 userAgent=DSub
Sep 18 21:38:23 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:23+01:00" level=debug msg="API: New request /rest/savePlayQueue.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000008 username=prupert version=1.2.0
Sep 18 21:38:23 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:23+01:00" level=debug msg="Found matching player" client=DSub id=cc2a618d-96c3-4a61-999e-c00e69c5faee requestId=hc2audioserver/Rjz9qY1bZV-000008 type=DSub username=prupert
Sep 18 21:38:23 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:23+01:00" level=debug msg="API: Successful response" endpoint=/rest/savePlayQueue.view requestId=hc2audioserver/Rjz9qY1bZV-000008 status=OK
Sep 18 21:38:23 hc2audioserver navidrome[18486]: time="2024-09-18T21:38:23+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/savePlayQueue.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&id=f9aa22fc5662d9f30ba40b117c729047&id=a77204808c96d2739d055a98b26901a3&id=9e32bfe65f74402bda36a1a09012f53d&id=bffc98fb978b8a73eef781bb92a3ed46&id=aaf4e847fa4137cebb193f8661f87dd9&id=54759f620e82720d81e8edb1badf07a5&id=4255c3fc5b1a453e49bbc88d20832fc9&id=9ad15f90a1bf3ebf7d4daba7e2c7ef8c&current=f9aa22fc5662d9f30ba40b117c729047&position=0" elapsedTime=49.5ms httpStatus=200 remoteAddr="192.168.1.44:40030" requestId=hc2audioserver/Rjz9qY1bZV-000008 responseSize=175 userAgent=DSub
Sep 18 21:42:14 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:14+01:00" level=debug msg="API: Successful response" endpoint=/rest/getUser.view requestId=hc2audioserver/Rjz9qY1bZV-000028 status=OK
Sep 18 21:42:14 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:14+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/getUser.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&username=prupert" elapsedTime=15.6ms httpStatus=200 remoteAddr="192.168.1.44:40030" requestId=hc2audioserver/Rjz9qY1bZV-000028 responseSize=474 userAgent=DSub
Sep 18 21:42:15 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:15+01:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000029 username=prupert version=1.2.0
Sep 18 21:42:15 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:15+01:00" level=debug msg="Processing GetDevice" user=prupert
Sep 18 21:42:15 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:15+01:00" level=info msg="JukeboxControl request received" action=set requestId=hc2audioserver/Rjz9qY1bZV-000029
Sep 18 21:42:15 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:15+01:00" level=debug msg="Processing Set action" device="Name: internal, Gain: 1.0000, Loaded track: %!s(<nil>)" ids="[]" requestId=hc2audioserver/Rjz9qY1bZV-000029
Sep 18 21:42:15 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:15+01:00" level=debug msg="Processing Clear action" device="Name: internal, Gain: 1.0000, Loaded track: %!s(<nil>)" requestId=hc2audioserver/Rjz9qY1bZV-000029
Sep 18 21:42:15 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:15+01:00" level=debug msg="Processing Add action" device="Name: internal, Gain: 1.0000, Loaded track: %!s(<nil>)" ids="[]" requestId=hc2audioserver/Rjz9qY1bZV-000029
Sep 18 21:42:15 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:15+01:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=hc2audioserver/Rjz9qY1bZV-000029 status=OK
Sep 18 21:42:15 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:15+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/jukeboxControl.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&action=set" elapsedTime=9.5ms httpStatus=200 remoteAddr="192.168.1.44:40030" requestId=hc2audioserver/Rjz9qY1bZV-000029 responseSize=249 userAgent=DSub
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000030 username=prupert version=1.2.0
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Processing GetDevice" user=prupert
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=info msg="JukeboxControl request received" action=set requestId=hc2audioserver/Rjz9qY1bZV-000030
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Processing Set action" device="Name: internal, Gain: 1.0000, Loaded track: %!s(<nil>)" ids="[]" requestId=hc2audioserver/Rjz9qY1bZV-000030
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Processing Clear action" device="Name: internal, Gain: 1.0000, Loaded track: %!s(<nil>)" requestId=hc2audioserver/Rjz9qY1bZV-000030
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Processing Add action" device="Name: internal, Gain: 1.0000, Loaded track: %!s(<nil>)" ids="[]" requestId=hc2audioserver/Rjz9qY1bZV-000030
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=hc2audioserver/Rjz9qY1bZV-000030 status=OK
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/jukeboxControl.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&action=set" elapsedTime=15.2ms httpStatus=200 remoteAddr="192.168.1.44:40030" requestId=hc2audioserver/Rjz9qY1bZV-000030 responseSize=249 userAgent=DSub
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000031 username=prupert version=1.2.0
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Processing GetDevice" user=prupert
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=info msg="JukeboxControl request received" action=set requestId=hc2audioserver/Rjz9qY1bZV-000031
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Processing Set action" device="Name: internal, Gain: 1.0000, Loaded track: %!s(<nil>)" ids="[f9aa22fc5662d9f30ba40b117c729047 a77204808c96d2739d055a98b26901a3 9e32bfe65f74402bda36a1a09012f53d bffc98fb978b8a73eef781bb92a3ed46 aaf4e847fa4137cebb193f8661f87dd9 54759f620e82720d81e8edb1badf07a5 4255c3fc5b1a453e49bbc88d20832fc9 9ad15f90a1bf3ebf7d4daba7e2c7ef8c]" requestId=hc2audioserver/Rjz9qY1bZV-000031
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Processing Clear action" device="Name: internal, Gain: 1.0000, Loaded track: %!s(<nil>)" requestId=hc2audioserver/Rjz9qY1bZV-000031
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Processing Add action" device="Name: internal, Gain: 1.0000, Loaded track: %!s(<nil>)" ids="[f9aa22fc5662d9f30ba40b117c729047 a77204808c96d2739d055a98b26901a3 9e32bfe65f74402bda36a1a09012f53d bffc98fb978b8a73eef781bb92a3ed46 aaf4e847fa4137cebb193f8661f87dd9 54759f620e82720d81e8edb1badf07a5 4255c3fc5b1a453e49bbc88d20832fc9 9ad15f90a1bf3ebf7d4daba7e2c7ef8c]" requestId=hc2audioserver/Rjz9qY1bZV-000031
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Found mediafile: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac" requestId=hc2audioserver/Rjz9qY1bZV-000031
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Found mediafile: /mnt/sda/FLAC/World/90s/Yogo Yogo/03-Ingani.flac" requestId=hc2audioserver/Rjz9qY1bZV-000031
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Found mediafile: /mnt/sda/FLAC/World/90s/Yogo Yogo/04-Amarumasi.flac" requestId=hc2audioserver/Rjz9qY1bZV-000031
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Found mediafile: /mnt/sda/FLAC/World/90s/Yogo Yogo/05-Kulani Kulani.flac" requestId=hc2audioserver/Rjz9qY1bZV-000031
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Found mediafile: /mnt/sda/FLAC/World/90s/Yogo Yogo/06-Hai Kamina.flac" requestId=hc2audioserver/Rjz9qY1bZV-000031
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="API: New request /rest/scrobble.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000032 username=prupert version=1.2.0
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Found matching player" client=DSub id=cc2a618d-96c3-4a61-999e-c00e69c5faee requestId=hc2audioserver/Rjz9qY1bZV-000032 type=DSub username=prupert
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Found mediafile: /mnt/sda/FLAC/World/90s/Yogo Yogo/07-Yogo Yogo.flac" requestId=hc2audioserver/Rjz9qY1bZV-000031
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Found mediafile: /mnt/sda/FLAC/World/90s/Yogo Yogo/08-Ti Samboko.flac" requestId=hc2audioserver/Rjz9qY1bZV-000031
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=info msg="Now Playing" artist="Penny Penny" player="DSub [DSub]" requestId=hc2audioserver/Rjz9qY1bZV-000032 title="Ibola Aids" user=prupert
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Found mediafile: /mnt/sda/FLAC/World/90s/Yogo Yogo/09-Ama Owners.flac" requestId=hc2audioserver/Rjz9qY1bZV-000031
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=hc2audioserver/Rjz9qY1bZV-000031 status=OK
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/jukeboxControl.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&action=set&id=f9aa22fc5662d9f30ba40b117c729047&id=a77204808c96d2739d055a98b26901a3&id=9e32bfe65f74402bda36a1a09012f53d&id=bffc98fb978b8a73eef781bb92a3ed46&id=aaf4e847fa4137cebb193f8661f87dd9&id=54759f620e82720d81e8edb1badf07a5&id=4255c3fc5b1a453e49bbc88d20832fc9&id=9ad15f90a1bf3ebf7d4daba7e2c7ef8c" elapsedTime=171.2ms httpStatus=200 remoteAddr="192.168.1.44:40030" requestId=hc2audioserver/Rjz9qY1bZV-000031 responseSize=248 userAgent=DSub
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Sending NowPlaying update" artist="Penny Penny" requestId=hc2audioserver/Rjz9qY1bZV-000032 scrobbler=lastfm track="Ibola Aids"
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="API: New request /rest/savePlayQueue.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000033 username=prupert version=1.2.0
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Found matching player" client=DSub id=cc2a618d-96c3-4a61-999e-c00e69c5faee requestId=hc2audioserver/Rjz9qY1bZV-000033 type=DSub username=prupert
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="API: Successful response" endpoint=/rest/savePlayQueue.view requestId=hc2audioserver/Rjz9qY1bZV-000033 status=OK
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/savePlayQueue.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&id=f9aa22fc5662d9f30ba40b117c729047&id=a77204808c96d2739d055a98b26901a3&id=9e32bfe65f74402bda36a1a09012f53d&id=bffc98fb978b8a73eef781bb92a3ed46&id=aaf4e847fa4137cebb193f8661f87dd9&id=54759f620e82720d81e8edb1badf07a5&id=4255c3fc5b1a453e49bbc88d20832fc9&id=9ad15f90a1bf3ebf7d4daba7e2c7ef8c&current=f9aa22fc5662d9f30ba40b117c729047&position=0" elapsedTime=16.5ms httpStatus=200 remoteAddr="192.168.1.44:40030" requestId=hc2audioserver/Rjz9qY1bZV-000033 responseSize=175 userAgent=DSub
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000034 username=prupert version=1.2.0
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Processing GetDevice" user=prupert
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=info msg="JukeboxControl request received" action=skip requestId=hc2audioserver/Rjz9qY1bZV-000034
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Processing Skip action" device="Name: internal, Gain: 1.0000, Loaded track: %!s(<nil>)" index=0 offset=0 requestId=hc2audioserver/Rjz9qY1bZV-000034
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Loading track" mediaType=audio/flac trackPath="/mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac"
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=info msg="Found mpv" path=/usr/bin/mpv
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Executing mpv command" cmd="[/usr/bin/mpv --no-audio-display --pause /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac --input-ipc-server=/tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket --audio-channels=stereo --audio-samplerate=48000 --audio-format=s16 --ao=pcm --ao-pcm-file=/tmp/mpd]"
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Sending NowPlaying update" artist="Penny Penny" requestId=hc2audioserver/Rjz9qY1bZV-000032 scrobbler=listenbrainz track="Ibola Aids"
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="API: Successful response" endpoint=/rest/scrobble.view requestId=hc2audioserver/Rjz9qY1bZV-000032 status=OK
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/scrobble.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&id=f9aa22fc5662d9f30ba40b117c729047&submission=false" elapsedTime=484.3ms httpStatus=200 remoteAddr="192.168.1.44:40032" requestId=hc2audioserver/Rjz9qY1bZV-000032 responseSize=175 userAgent=DSub
Sep 18 21:42:37 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:37+01:00" level=debug msg="Socket found" retries=10 waitTime=1.01s
Sep 18 21:42:37 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:37+01:00" level=debug msg="Setting volume" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket" volume=1
Sep 18 21:42:37 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:37+01:00" level=debug msg="Setting position" offset=0 track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket"
Sep 18 21:42:37 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:37+01:00" level=debug msg="Got mpv error, retrying..." error="mpv error: property unavailable" retries=1
Sep 18 21:42:37 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:37+01:00" level=debug msg="No position difference, skipping operation" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket"
Sep 18 21:42:37 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:37+01:00" level=debug msg="Got mpv error, retrying..." error="mpv error: property unavailable" retries=1
Sep 18 21:42:37 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:37+01:00" level=debug msg="Checking if track is playing" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket"
Sep 18 21:42:37 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:37+01:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=hc2audioserver/Rjz9qY1bZV-000034 status=OK
Sep 18 21:42:37 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:37+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/jukeboxControl.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&action=skip&index=0&offset=0" elapsedTime=1.03s httpStatus=200 remoteAddr="192.168.1.44:40080" requestId=hc2audioserver/Rjz9qY1bZV-000034 responseSize=248 userAgent=DSub
Sep 18 21:42:41 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:41+01:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000035 username=prupert version=1.2.0
Sep 18 21:42:41 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:41+01:00" level=debug msg="Processing GetDevice" user=prupert
Sep 18 21:42:41 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:41+01:00" level=info msg="JukeboxControl request received" action=status requestId=hc2audioserver/Rjz9qY1bZV-000035
Sep 18 21:42:41 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:41+01:00" level=debug msg="processing Status action on: Name: internal, Gain: 1.0000, Loaded track: Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket, queue: #Items: 8, idx: 0, files: 0:/mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac 1:/mnt/sda/FLAC/World/90s/Yogo Yogo/03-Ingani.flac 2:/mnt/sda/FLAC/World/90s/Yogo Yogo/04-Amarumasi.flac 3:/mnt/sda/FLAC/World/90s/Yogo Yogo/05-Kulani Kulani.flac 4:/mnt/sda/FLAC/World/90s/Yogo Yogo/06-Hai Kamina.flac 5:/mnt/sda/FLAC/World/90s/Yogo Yogo/07-Yogo Yogo.flac 6:/mnt/sda/FLAC/World/90s/Yogo Yogo/08-Ti Samboko.flac 7:/mnt/sda/FLAC/World/90s/Yogo Yogo/09-Ama Owners.flac " requestId=hc2audioserver/Rjz9qY1bZV-000035
Sep 18 21:42:41 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:41+01:00" level=debug msg="Checking if track is playing" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket"
Sep 18 21:42:41 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:41+01:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=hc2audioserver/Rjz9qY1bZV-000035 status=OK
Sep 18 21:42:41 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:41+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/jukeboxControl.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&action=status" elapsedTime=26.9ms httpStatus=200 remoteAddr="192.168.1.44:40030" requestId=hc2audioserver/Rjz9qY1bZV-000035 responseSize=248 userAgent=DSub
Sep 18 21:42:46 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:46+01:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000036 username=prupert version=1.2.0
Sep 18 21:42:46 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:46+01:00" level=debug msg="Processing GetDevice" user=prupert
Sep 18 21:42:46 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:46+01:00" level=info msg="JukeboxControl request received" action=status requestId=hc2audioserver/Rjz9qY1bZV-000036
Sep 18 21:42:46 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:46+01:00" level=debug msg="processing Status action on: Name: internal, Gain: 1.0000, Loaded track: Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket, queue: #Items: 8, idx: 0, files: 0:/mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac 1:/mnt/sda/FLAC/World/90s/Yogo Yogo/03-Ingani.flac 2:/mnt/sda/FLAC/World/90s/Yogo Yogo/04-Amarumasi.flac 3:/mnt/sda/FLAC/World/90s/Yogo Yogo/05-Kulani Kulani.flac 4:/mnt/sda/FLAC/World/90s/Yogo Yogo/06-Hai Kamina.flac 5:/mnt/sda/FLAC/World/90s/Yogo Yogo/07-Yogo Yogo.flac 6:/mnt/sda/FLAC/World/90s/Yogo Yogo/08-Ti Samboko.flac 7:/mnt/sda/FLAC/World/90s/Yogo Yogo/09-Ama Owners.flac " requestId=hc2audioserver/Rjz9qY1bZV-000036
Sep 18 21:42:46 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:46+01:00" level=debug msg="Checking if track is playing" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket"
Sep 18 21:42:46 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:46+01:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=hc2audioserver/Rjz9qY1bZV-000036 status=OK
Sep 18 21:42:46 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:46+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/jukeboxControl.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&action=status" elapsedTime=19.4ms httpStatus=200 remoteAddr="192.168.1.44:40030" requestId=hc2audioserver/Rjz9qY1bZV-000036 responseSize=248 userAgent=DSub
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000037 username=prupert version=1.2.0
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=debug msg="Processing GetDevice" user=prupert
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=info msg="JukeboxControl request received" action=set requestId=hc2audioserver/Rjz9qY1bZV-000037
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=debug msg="Processing Set action" device="Name: internal, Gain: 1.0000, Loaded track: Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket" ids="[]" requestId=hc2audioserver/Rjz9qY1bZV-000037
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=debug msg="Processing Clear action" device="Name: internal, Gain: 1.0000, Loaded track: Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket" requestId=hc2audioserver/Rjz9qY1bZV-000037
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=debug msg="Pausing track" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket"
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=debug msg="Closing resources" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket"
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=debug msg="sending shutdown command"
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=debug msg="Removing socketfile" socketfile=/tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=debug msg="Processing Add action" device="Name: internal, Gain: 1.0000, Loaded track: %!s(<nil>)" ids="[]" requestId=hc2audioserver/Rjz9qY1bZV-000037
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=hc2audioserver/Rjz9qY1bZV-000037 status=OK
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/jukeboxControl.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&action=set" elapsedTime=23.9ms httpStatus=200 remoteAddr="192.168.1.44:40030" requestId=hc2audioserver/Rjz9qY1bZV-000037 responseSize=249 userAgent=DSub
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=info msg="Hitting end-of-stream, signalling on channel"
Sep 18 21:42:51 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:51+01:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000038 username=prupert version=1.2.0
Sep 18 21:42:51 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:51+01:00" level=debug msg="Processing GetDevice" user=prupert
Sep 18 21:42:51 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:51+01:00" level=info msg="JukeboxControl request received" action=status requestId=hc2audioserver/Rjz9qY1bZV-000038
Sep 18 21:42:51 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:51+01:00" level=debug msg="processing Status action on: Name: internal, Gain: 1.0000, Loaded track: %!s(<nil>), queue: #Items: 0, idx: -1, files: " requestId=hc2audioserver/Rjz9qY1bZV-000038
Sep 18 21:42:51 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:51+01:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=hc2audioserver/Rjz9qY1bZV-000038 status=OK
Sep 18 21:42:51 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:51+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/jukeboxControl.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&action=status" elapsedTime=8ms httpStatus=200 remoteAddr="192.168.1.44:40030" requestId=hc2audioserver/Rjz9qY1bZV-000038 responseSize=249 userAgent=DSub

pruperting commented 2 months ago

Seems like it quickly skips to the end of the track away and mpv is told to stop playing

Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=info msg="Found mpv" path=/usr/bin/mpv
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Executing mpv command" cmd="[/usr/bin/mpv --no-audio-display --pause /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac --input-ipc-server=/tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket --audio-channels=stereo --audio-samplerate=48000 --audio-format=s16 --ao=pcm --ao-pcm-file=/tmp/mpd]"
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="Sending NowPlaying update" artist="Penny Penny" requestId=hc2audioserver/Rjz9qY1bZV-000032 scrobbler=listenbrainz track="Ibola Aids"
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="API: Successful response" endpoint=/rest/scrobble.view requestId=hc2audioserver/Rjz9qY1bZV-000032 status=OK
Sep 18 21:42:36 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:36+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/scrobble.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&id=f9aa22fc5662d9f30ba40b117c729047&submission=false" elapsedTime=484.3ms httpStatus=200 remoteAddr="192.168.1.44:40032" requestId=hc2audioserver/Rjz9qY1bZV-000032 responseSize=175 userAgent=DSub
Sep 18 21:42:37 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:37+01:00" level=debug msg="Socket found" retries=10 waitTime=1.01s
Sep 18 21:42:37 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:37+01:00" level=debug msg="Setting volume" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket" volume=1
Sep 18 21:42:37 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:37+01:00" level=debug msg="Setting position" offset=0 track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket"
Sep 18 21:42:37 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:37+01:00" level=debug msg="Got mpv error, retrying..." error="mpv error: property unavailable" retries=1
Sep 18 21:42:37 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:37+01:00" level=debug msg="No position difference, skipping operation" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket"
Sep 18 21:42:37 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:37+01:00" level=debug msg="Got mpv error, retrying..." error="mpv error: property unavailable" retries=1
Sep 18 21:42:37 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:37+01:00" level=debug msg="Checking if track is playing" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket"
Sep 18 21:42:37 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:37+01:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=hc2audioserver/Rjz9qY1bZV-000034 status=OK
Sep 18 21:42:37 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:37+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/jukeboxControl.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&action=skip&index=0&offset=0" elapsedTime=1.03s httpStatus=200 remoteAddr="192.168.1.44:40080" requestId=hc2audioserver/Rjz9qY1bZV-000034 responseSize=248 userAgent=DSub
Sep 18 21:42:41 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:41+01:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000035 username=prupert version=1.2.0
Sep 18 21:42:41 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:41+01:00" level=debug msg="Processing GetDevice" user=prupert
Sep 18 21:42:41 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:41+01:00" level=info msg="JukeboxControl request received" action=status requestId=hc2audioserver/Rjz9qY1bZV-000035
Sep 18 21:42:41 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:41+01:00" level=debug msg="processing Status action on: Name: internal, Gain: 1.0000, Loaded track: Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket, queue: #Items: 8, idx: 0, files: 0:/mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac 1:/mnt/sda/FLAC/World/90s/Yogo Yogo/03-Ingani.flac 2:/mnt/sda/FLAC/World/90s/Yogo Yogo/04-Amarumasi.flac 3:/mnt/sda/FLAC/World/90s/Yogo Yogo/05-Kulani Kulani.flac 4:/mnt/sda/FLAC/World/90s/Yogo Yogo/06-Hai Kamina.flac 5:/mnt/sda/FLAC/World/90s/Yogo Yogo/07-Yogo Yogo.flac 6:/mnt/sda/FLAC/World/90s/Yogo Yogo/08-Ti Samboko.flac 7:/mnt/sda/FLAC/World/90s/Yogo Yogo/09-Ama Owners.flac " requestId=hc2audioserver/Rjz9qY1bZV-000035
Sep 18 21:42:41 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:41+01:00" level=debug msg="Checking if track is playing" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket"
Sep 18 21:42:41 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:41+01:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=hc2audioserver/Rjz9qY1bZV-000035 status=OK
Sep 18 21:42:41 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:41+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/jukeboxControl.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&action=status" elapsedTime=26.9ms httpStatus=200 remoteAddr="192.168.1.44:40030" requestId=hc2audioserver/Rjz9qY1bZV-000035 responseSize=248 userAgent=DSub
Sep 18 21:42:46 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:46+01:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000036 username=prupert version=1.2.0
Sep 18 21:42:46 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:46+01:00" level=debug msg="Processing GetDevice" user=prupert
Sep 18 21:42:46 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:46+01:00" level=info msg="JukeboxControl request received" action=status requestId=hc2audioserver/Rjz9qY1bZV-000036
Sep 18 21:42:46 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:46+01:00" level=debug msg="processing Status action on: Name: internal, Gain: 1.0000, Loaded track: Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket, queue: #Items: 8, idx: 0, files: 0:/mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac 1:/mnt/sda/FLAC/World/90s/Yogo Yogo/03-Ingani.flac 2:/mnt/sda/FLAC/World/90s/Yogo Yogo/04-Amarumasi.flac 3:/mnt/sda/FLAC/World/90s/Yogo Yogo/05-Kulani Kulani.flac 4:/mnt/sda/FLAC/World/90s/Yogo Yogo/06-Hai Kamina.flac 5:/mnt/sda/FLAC/World/90s/Yogo Yogo/07-Yogo Yogo.flac 6:/mnt/sda/FLAC/World/90s/Yogo Yogo/08-Ti Samboko.flac 7:/mnt/sda/FLAC/World/90s/Yogo Yogo/09-Ama Owners.flac " requestId=hc2audioserver/Rjz9qY1bZV-000036
Sep 18 21:42:46 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:46+01:00" level=debug msg="Checking if track is playing" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket"
Sep 18 21:42:46 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:46+01:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=hc2audioserver/Rjz9qY1bZV-000036 status=OK
Sep 18 21:42:46 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:46+01:00" level=debug msg="HTTP: GET http://192.168.1.22:4533/rest/jukeboxControl.view?u=prupert&s=dvmd5ah8u7q06d5ts834eh3o6u&t=50b61dd7b597e48541be29dc26df1e2e&v=1.2.0&c=DSub&action=status" elapsedTime=19.4ms httpStatus=200 remoteAddr="192.168.1.44:40030" requestId=hc2audioserver/Rjz9qY1bZV-000036 responseSize=248 userAgent=DSub
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=hc2audioserver/Rjz9qY1bZV-000037 username=prupert version=1.2.0
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=debug msg="Processing GetDevice" user=prupert
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=info msg="JukeboxControl request received" action=set requestId=hc2audioserver/Rjz9qY1bZV-000037
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=debug msg="Processing Set action" device="Name: internal, Gain: 1.0000, Loaded track: Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket" ids="[]" requestId=hc2audioserver/Rjz9qY1bZV-000037
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=debug msg="Processing Clear action" device="Name: internal, Gain: 1.0000, Loaded track: Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket" requestId=hc2audioserver/Rjz9qY1bZV-000037
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=debug msg="Pausing track" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket"
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=debug msg="Closing resources" track="Name: /mnt/sda/FLAC/World/90s/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-e0a91f24-ce68-406a-8083-c1fc00ae7f26.socket"
Sep 18 21:42:47 hc2audioserver navidrome[18486]: time="2024-09-18T21:42:47+01:00" level=debug msg="sending shutdown command"

pruperting commented 2 months ago

Updated to the most recent version today, the logs are slightly different, but behaviour is the same, the file starts to play, but no audio heard, then the file skips forward to the next track and this continues to the end of the playlist. Log here: https://gist.github.com/pruperting/9c8ac97e73e4fc75acfdd64ddcb06237

pruperting commented 2 months ago

@pruperting Just to be sure: Did you remove the MPVPath from your config as well? You should have these lines in the beginning of your logs:
    MPVPath:                         "",
    MPVCmdTemplate:                  "mpv --audio-device=%d --no-audio-display --pause %f --input-ipc-server=%s",
Can you confirm?

Hey @ms140569, can you take a look whenever you have time? I don't see any issues based on the logs....

Sorry, I misread this, you want MPVPath to be cleared, will do that and ensure the MPVtemplate reflects what you have there. Watch this space.

pruperting commented 2 months ago

Right, yes MPVPath is not in config and I see those two entries in the beginning of my logs:

Sep 19 22:24:08 prupert-OptiPlex-3060 navidrome[4441]:     FFmpegPath:                      "",
Sep 19 22:24:08 prupert-OptiPlex-3060 navidrome[4441]:     MPVPath:                         "",
Sep 19 22:24:08 prupert-OptiPlex-3060 navidrome[4441]:     MPVCmdTemplate:                  "mpv --audio-device=%d --no-audio-display --pause %f --input-ipc-server=%s",
Sep 19 22:24:08 prupert-OptiPlex-3060 navidrome[4441]:     CoverArtPriority:                "cover.*, folder.*, front.*, embedded, external",

But I am seeing the same issues with Jukebox mode not appearing to work:

Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=info msg="JukeboxControl request received" action=skip requestId=prupert-OptiPlex-3060/BWmUFZ2OHt-000025
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="Processing Skip action" device="Name: auto, Gain: 1.0000, Loaded track: %!s(<nil>)" index=0 offset=0 requestId=prupert-OptiPlex-3060/BWmUFZ2OHt-000025
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="Loading track" mediaType=audio/flac trackPath="/home/prupert/Music/Yogo Yogo/02-Ibola Aids.flac"
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=info msg="Found mpv" path=/usr/bin/mpv
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="Executing mpv command" cmd="[/usr/bin/mpv --audio-device=auto --no-audio-display --pause /home/prupert/Music/Yogo Yogo/02-Ibola Aids.flac --input-ipc-server=/tmp/mpv-ctrl-d80f44af-b5aa-43d8-8911-0ca7f7f95a36.socket]"
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="API: New request /rest/scrobble.view" client=DSub requestId=prupert-OptiPlex-3060/BWmUFZ2OHt-000026 username=admin version=1.2.0
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="Found matching player" client=DSub id=bd549062-00f4-4f5a-bb64-3752a160dd1a requestId=prupert-OptiPlex-3060/BWmUFZ2OHt-000026 type=DSub username=admin
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=info msg="Now Playing" artist="Penny Penny" player="DSub [DSub]" requestId=prupert-OptiPlex-3060/BWmUFZ2OHt-000026 title="Ibola Aids" user=admin
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="API: Successful response" endpoint=/rest/scrobble.view requestId=prupert-OptiPlex-3060/BWmUFZ2OHt-000026 status=OK
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="HTTP: GET http://192.168.1.34:4533/rest/scrobble.view?u=admin&s=[REDACTED]&t=[REDACTED]&v=1.2.0&c=DSub&id=b56679cc6b2165e9e8ca6d01abc280a1&submission=false" elapsedTime=2.1ms httpStatus=200 remoteAddr="192.168.1.44:42310" requestId=prupert-OptiPlex-3060/BWmUFZ2OHt-000026 responseSize=175 userAgent=DSub
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="API: New request /rest/savePlayQueue.view" client=DSub requestId=prupert-OptiPlex-3060/BWmUFZ2OHt-000027 username=admin version=1.2.0
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="Found matching player" client=DSub id=bd549062-00f4-4f5a-bb64-3752a160dd1a requestId=prupert-OptiPlex-3060/BWmUFZ2OHt-000027 type=DSub username=admin
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="API: Successful response" endpoint=/rest/savePlayQueue.view requestId=prupert-OptiPlex-3060/BWmUFZ2OHt-000027 status=OK
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="HTTP: GET http://192.168.1.34:4533/rest/savePlayQueue.view?u=admin&s=[REDACTED]&t=[REDACTED]&v=1.2.0&c=DSub&id=b56679cc6b2165e9e8ca6d01abc280a1&id=1672dfccd93cc5174262c28ec501a729&id=d7b2b67be4a41df387b4e7558215d2c5&id=5af7f3ef04a835be96c9cecd89562b56&id=c29ed24f033a1c1931a1dc026d449068&id=e718156c8d4cdaa8efb7e425a8f6bf02&id=ed00076715766b48932d9ec4abb474b7&id=b1a81918a6c5452f9dcf39f1af6e1d7b&current=b56679cc6b2165e9e8ca6d01abc280a1&position=0" elapsedTime=1.1ms httpStatus=200 remoteAddr="192.168.1.44:42310" requestId=prupert-OptiPlex-3060/BWmUFZ2OHt-000027 responseSize=175 userAgent=DSub
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="Socket found" retries=1 waitTime=101.1ms
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="Setting volume" track="Name: /home/prupert/Music/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-d80f44af-b5aa-43d8-8911-0ca7f7f95a36.socket" volume=1
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="Setting position" offset=0 track="Name: /home/prupert/Music/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-d80f44af-b5aa-43d8-8911-0ca7f7f95a36.socket"
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="Got mpv error, retrying..." error="mpv error: property unavailable" retries=1
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="Got mpv error, retrying..." error="mpv error: property unavailable" retries=2
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="Got mpv error, retrying..." error="mpv error: property unavailable" retries=3
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=info msg="Hitting end-of-stream, signalling on channel"
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=error msg="Error getting position in track" error="trying to send command on closed mpv client" track="Name: /home/prupert/Music/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-d80f44af-b5aa-43d8-8911-0ca7f7f95a36.socket"
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="No position difference, skipping operation" track="Name: /home/prupert/Music/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-d80f44af-b5aa-43d8-8911-0ca7f7f95a36.socket"
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=error msg="Error getting position in track" error="trying to send command on closed mpv client" track="Name: /home/prupert/Music/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-d80f44af-b5aa-43d8-8911-0ca7f7f95a36.socket"
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="Checking if track is playing" track="Name: /home/prupert/Music/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-d80f44af-b5aa-43d8-8911-0ca7f7f95a36.socket"
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=error msg="Problem getting paused status" error="trying to send command on closed mpv client" track="Name: /home/prupert/Music/Yogo Yogo/02-Ibola Aids.flac, Socket: /tmp/mpv-ctrl-d80f44af-b5aa-43d8-8911-0ca7f7f95a36.socket"
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=prupert-OptiPlex-3060/BWmUFZ2OHt-000025 status=OK
Sep 19 22:25:21 prupert-OptiPlex-3060 navidrome[4441]: time="2024-09-19T22:25:21+01:00" level=debug msg="HTTP: GET http://192.168.1.34:4533/rest/jukeboxControl.view?u=admin&s=[REDACTED]&t=[REDACTED]&v=1.2.0&c=DSub&action=skip&index=0&offset=0" elapsedTime=240.7ms httpStatus=200 remoteAddr="192.168.1.44:42304" requestId=prupert-OptiPlex-3060/BWmUFZ2OHt-000025 responseSize=248 userAgent=DSub

ms140569 commented 2 months ago

@pruperting Could you provide the "ls -l" output for the socket control file to see how it's flagged and the user navidrome is running with? The Socket file is the one given with the input-ipc-server option, like:

--input-ipc-server=/tmp/mpv-ctrl-****.socket

mpv is quite a beast and every now and then the socket control doesn't work ...

PS: For further troubleshooting you might:

a) Run the mpv command without the --pause flag with the very same user which navidrome is running with. b) Lookup the process list with ps, including all arguments while the song should be played to see if something is missing

pruperting commented 2 months ago

Hiya - so the socket file does not get created by the navidrome process, there is no file (hence ls -l yields an error). If I run the mpv command from the logs as the same user as navdrome is run as on a default ubuntu install, the socket file IS created and the audio file is played by mpv as expected. So there is some issue with the system call navidrome is executing that means the socket file fails (I am guessing mpv is not being executed).

pruperting commented 2 months ago

Ooh, just noted, turning the logs to Trace, I see these errors when trying to use jukebox mode - presume these are coming from mpv?

Sep 25 21:41:10 prupert-OptiPlex-3060 navidrome[5576]: time="2024-09-25T21:41:10+01: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.53.0 (910a4612)\" openSubsonic=\"true\"></subsonic-response>" endpoint=/rest/scrobble.view requestId=prupert-OptiPlex-3060/snXh1NHyZJ-000014 status=OK
Sep 25 21:41:10 prupert-OptiPlex-3060 navidrome[5576]: time="2024-09-25T21:41:10+01:00" level=debug msg="HTTP: GET http://192.168.1.34:4533/rest/scrobble.view?u=admin&s=[REDACTED]&t=[REDACTED]&v=1.2.0&c=DSub&id=ed00076715766b48932d9ec4abb474b7&submission=false" elapsedTime=3ms header="{\"Accept-Encoding\":[\"gzip\"],\"Authorization\":[\"\"],\"Connection\":[\"Keep-Alive\"],\"Cookie\":[\"$Version=\\\"1\\\"; nd-player-61646d696e=\\\"bd549062-00f4-4f5a-bb64-3752a160dd1a\\\";$Path=\\\"/\\\";$Domain=\\\"192.168.1.34\\\"\"],\"User-Agent\":[\"DSub\"]}" httpStatus=200 remoteAddr="192.168.1.24:42320" requestId=prupert-OptiPlex-3060/snXh1NHyZJ-000014 responseSize=175
Sep 25 21:41:10 prupert-OptiPlex-3060 navidrome[5680]: [ao/alsa] Playback open error: Host is down
Sep 25 21:41:10 prupert-OptiPlex-3060 navidrome[5680]: Cannot connect to server socket err = No such file or directory
Sep 25 21:41:10 prupert-OptiPlex-3060 navidrome[5680]: Cannot connect to server request channel
Sep 25 21:41:10 prupert-OptiPlex-3060 navidrome[5576]: time="2024-09-25T21:41:10+01:00" level=debug msg="Socket found" retries=1 waitTime=100.4ms
Sep 25 21:41:10 prupert-OptiPlex-3060 navidrome[5576]: time="2024-09-25T21:41:10+01:00" level=debug msg="Setting volume" track="Name: /home/prupert/Music/Yogo Yogo/08-Ti Samboko.flac, Socket: /tmp/mpv-ctrl-642cd838-ccb4-40e8-a1a3-4b869d12784c.socket" volume=1
Sep 25 21:41:10 prupert-OptiPlex-3060 navidrome[5680]: jack server is not running or cannot be started
Sep 25 21:41:10 prupert-OptiPlex-3060 navidrome[5680]: JackShmReadWritePtr::~JackShmReadWritePtr - Init not done for -1, skipping unlock
Sep 25 21:41:10 prupert-OptiPlex-3060 navidrome[5680]: JackShmReadWritePtr::~JackShmReadWritePtr - Init not done for -1, skipping unlock
Sep 25 21:41:10 prupert-OptiPlex-3060 navidrome[5680]: [ao/jack] cannot open server
Sep 25 21:41:10 prupert-OptiPlex-3060 navidrome[5680]: [ao/sdl] could not open audio: ALSA: Couldn't open audio device: Host is down
Sep 25 21:41:10 prupert-OptiPlex-3060 navidrome[5680]: [ao] Failed to initialize audio driver 'sdl'
Sep 25 21:41:10 prupert-OptiPlex-3060 navidrome[5680]: Could not open/initialize audio device -> no sound.
Sep 25 21:41:10 prupert-OptiPlex-3060 navidrome[5680]: (Paused) : 00:00:00 / 00:06:01 (0%)
Sep 25 21:41:10 prupert-OptiPlex-3060 navidrome[5576]: time="2024-09-25T21:41:10+01:00" level=debug msg="Setting position" offset=0 track="Name: /home/prupert/Music/Yogo Yogo/08-Ti Samboko.flac, Socket: /tmp/mpv-ctrl-642cd838-ccb4-40e8-a1a3-4b869d12784c.socket"
Sep 25 21:41:10 prupert-OptiPlex-3060 navidrome[5576]: time="2024-09-25T21:41:10+01:00" level=info msg="Hitting end-of-stream, signalling on channel"
Sep 25 21:41:27 prupert-OptiPlex-3060 navidrome[5576]: time="2024-09-25T21:41:27+01:00" level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub requestId=prupert-OptiPlex-3060/snXh1NHyZJ-000015 username=admin version=1.2.0

pruperting commented 2 months ago

But running the mpv command as the same user as navidrome runs fine. Huh?

ms140569 commented 2 months ago

Hiya - so the socket file does not get created by the navidrome process, there is no file (hence ls -l yields an error). If I run the mpv command from the logs as the same user as navdrome is run as on a default ubuntu install, the socket file IS created and the audio file is played by mpv as expected. So there is some issue with the system call navidrome is executing that means the socket file fails (I am guessing mpv is not being executed).

Sure, the socketfile is created by the mpv command. I wanted to know with which security flags the file gets created.

But if I understand you correctly, the mpv process will not be created, correct?

Looking at your logs it seems to me that your ALSA Setup seems to be not working. Could you - for debugging purposes - try another output device?

pruperting commented 1 month ago

Hiya - so the socket file does not get created by the navidrome process, there is no file (hence ls -l yields an error). If I run the mpv command from the logs as the same user as navdrome is run as on a default ubuntu install, the socket file IS created and the audio file is played by mpv as expected. So there is some issue with the system call navidrome is executing that means the socket file fails (I am guessing mpv is not being executed).

Sure, the socketfile is created by the mpv command. I wanted to know with which security flags the file gets created.

But if I understand you correctly, the mpv process will not be created, correct?

Looking at your logs it seems to me that your ALSA Setup seems to be not working. Could you - for debugging purposes - try another output device?

Sure thing, let me try that out.

pruperting commented 1 month ago

Hiya - so the socket file does not get created by the navidrome process, there is no file (hence ls -l yields an error). If I run the mpv command from the logs as the same user as navdrome is run as on a default ubuntu install, the socket file IS created and the audio file is played by mpv as expected. So there is some issue with the system call navidrome is executing that means the socket file fails (I am guessing mpv is not being executed).

Sure, the socketfile is created by the mpv command. I wanted to know with which security flags the file gets created. But if I understand you correctly, the mpv process will not be created, correct? Looking at your logs it seems to me that your ALSA Setup seems to be not working. Could you - for debugging purposes - try another output device?

Sure thing, let me try that out.

Righty, I've tried a different audio output device. I can confirm executing the mpv command shown in the logs manually, this works fine and I can hear the audio playing, I also so no ASLA errors in the debug logs anymore.

I can also confirm the mpv process is called by navidrome as I can see it being called via "htop". However, same behaviour as before, where Dsub skips from one track to the next until the end of the playlist, with no audio being played and there continues to be issues with the socket file which doesn't appear to be created. I believe this is why the tracks are skipping forward as navidrome can't tell if the current file is playing.

pruperting commented 1 month ago

Looks like after executing the mpv command, it instantly hits the end of the file and moves to the next one. I don't see a socket file as it gets removed and quickly as it is created:

Oct 03 18:51:38 hc2audioserver navidrome[25129]: time="2024-10-03T18:51:38+01:00" level=debug msg="Switching to next song" queue="#Items: 13, idx: 8, files: 0:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/01-Zuton Fever.flac 1:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/02-Pressure Point.flac 2:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/03-You Will You Won’t.flac 3:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/04-Confusion.flac 4:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/05-Havana Gang Brawl.flac 5:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/06-Railroad.flac 6:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/07-Long Time Coming.flac 7:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/08-Nightmare Part II.flac 8:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/09-Not a Lot to Do.flac 9:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/10-Remember Me.flac 10:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/11-Dirty Dancehall.flac 11:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/12-Moons and Horror Shows.flac 12:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/13-Don’t Ever Think (Too Much).flac "
Oct 03 18:51:38 hc2audioserver navidrome[25129]: time="2024-10-03T18:51:38+01:00" level=debug msg="Loading track" mediaType=audio/flac trackPath="/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/09-Not a Lot to Do.flac"
Oct 03 18:51:38 hc2audioserver navidrome[25129]: time="2024-10-03T18:51:38+01:00" level=debug msg="Executing mpv command" cmd="[/usr/bin/mpv --log-file=/tmp/mpv.log --msg-level=all=info --no-audio-display '/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/09-Not a Lot to Do.flac' --input-ipc-server=/tmp/mpv-ctrl-e4f11948-6a87-48c9-aadf-7839b53c602f.socket]"
Oct 03 18:51:38 hc2audioserver navidrome[25129]: time="2024-10-03T18:51:38+01:00" level=debug msg="Socket found" retries=9 waitTime=907.7ms
Oct 03 18:51:38 hc2audioserver navidrome[25129]: time="2024-10-03T18:51:38+01:00" level=debug msg="Setting volume" track="Name: /mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/09-Not a Lot to Do.flac, Socket: /tmp/mpv-ctrl-e4f11948-6a87-48c9-aadf-7839b53c602f.socket" volume=1
Oct 03 18:51:38 hc2audioserver navidrome[25129]: time="2024-10-03T18:51:38+01:00" level=info msg="Hitting end-of-stream, signalling on channel"
Oct 03 18:51:38 hc2audioserver navidrome[25129]: time="2024-10-03T18:51:38+01:00" level=debug msg="Unpausing track" track="Name: /mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/09-Not a Lot to Do.flac, Socket: /tmp/mpv-ctrl-e4f11948-6a87-48c9-aadf-7839b53c602f.socket"
Oct 03 18:51:38 hc2audioserver navidrome[25129]: time="2024-10-03T18:51:38+01:00" level=error msg="Error unpausing track" error="trying to send command on closed mpv client" track="Name: /mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/09-Not a Lot to Do.flac, Socket: /tmp/mpv-ctrl-e4f11948-6a87-48c9-aadf-7839b53c602f.socket"
Oct 03 18:51:38 hc2audioserver navidrome[25129]: time="2024-10-03T18:51:38+01:00" level=debug msg="Track switching detected"
Oct 03 18:51:38 hc2audioserver navidrome[25129]: time="2024-10-03T18:51:38+01:00" level=debug msg="Closing resources" track="Name: /mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/09-Not a Lot to Do.flac, Socket: /tmp/mpv-ctrl-e4f11948-6a87-48c9-aadf-7839b53c602f.socket"
Oct 03 18:51:38 hc2audioserver navidrome[25129]: time="2024-10-03T18:51:38+01:00" level=debug msg="sending shutdown command"
Oct 03 18:51:38 hc2audioserver navidrome[25129]: time="2024-10-03T18:51:38+01:00" level=warning msg="Error sending quit command to mpv-ipc socket" error="trying to send command on closed mpv client"
Oct 03 18:51:38 hc2audioserver navidrome[25129]: time="2024-10-03T18:51:38+01:00" level=debug msg="cancelling executor"
Oct 03 18:51:38 hc2audioserver navidrome[25129]: time="2024-10-03T18:51:38+01:00" level=debug msg="Removing socketfile" socketfile=/tmp/mpv-ctrl-e4f11948-6a87-48c9-aadf-7839b53c602f.socket
Oct 03 18:51:38 hc2audioserver navidrome[25129]: time="2024-10-03T18:51:38+01:00" level=debug msg="Switching to next song" queue="#Items: 13, idx: 9, files: 0:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/01-Zuton Fever.flac 1:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/02-Pressure Point.flac 2:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/03-You Will You Won’t.flac 3:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/04-Confusion.flac 4:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/05-Havana Gang Brawl.flac 5:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/06-Railroad.flac 6:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/07-Long Time Coming.flac 7:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/08-Nightmare Part II.flac 8:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/09-Not a Lot to Do.flac 9:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/10-Remember Me.flac 10:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/11-Dirty Dancehall.flac 11:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/12-Moons and Horror Shows.flac 12:/mnt/sda/FLAC/Indie/00s/Who Killed The Zutons/13-Don’t Ever Think (Too Much).flac "

pruperting commented 1 month ago

So, not a fix, but in the meantime, I am using this: https://www.lesbonscomptes.com/upmpdcli/index.html which acts as a UPNP media renderer (using mpd). The Android Symfonium app can cast songs from Navidrome to upmpdcli and I've set up mpd to play to a FIFO that snapserver then broadcasts to my other snapcast clients. It works really well! This is a much nicer app to use than dsub, so I prefer this setup actually.

thulard commented 2 weeks ago

So, not a fix, but in the meantime, I am using this: https://www.lesbonscomptes.com/upmpdcli/index.html which acts as a UPNP media renderer (using mpd). The Android Symfonium app can cast songs from Navidrome to upmpdcli and I've set up mpd to play to a FIFO that snapserver then broadcasts to my other snapcast clients. It works really well! This is a much nicer app to use than dsub, so I prefer this setup actually.

Hi @pruperting , don't want to derailed the bug report but would you mind sharing your upmpdcli config? Thanks

navidrome / navidrome