Open julienlag opened 5 months ago
Confirming the same issue. I have updated the default Ubuntu 0.32.0-1ubuntu1 to 0.36.0+fruit~ubuntu2004 without any change.
Same issue here on a raspberry pi 3b+ running OSMC The command starting MPV works when typed manually in the terminal but fails when initated by navidrome with the error : "got the mpv error: property unavailable error, retry ..."
Navidrome is installed from the official binary and run as a systemd service. I thought it could be related to that but I get the same error if I start Navidrome manually.
I cannot reproduce this error here with DSub. For Ultrasonic, there is another issue that prevents it to work properly with Navidrome: https://gitlab.com/ultrasonic/ultrasonic/-/issues/1266
I'll release a new version in the next couple of days, with the change mentioned in the Ultrasonic's issue, but not sure if this will have any effect on this issue here.
If you don't want to wait for the release and want to test right away, you can use the latest development build: https://nightly.link/navidrome/navidrome/workflows/pipeline/master
Tried with the latest nightly and I still get the same error using DSub and Ultrasonic.
Tried with DSUB and get the same error. Is it possibly restricted to Ubuntu?
thanks @deluan for looking into this! Unfortunately this hasn't solved the issue for me (neither with Ultrasonic nor DSub).
Server version: [0.50.1-SNAPSHOT] (2b33ef72)
Output from journalctl -f -u navidrome.service |grep level=error
upon pressing "Play" on Ultrasonic with Jukebox function 'on':
Jan 21 20:54:23 myservice navidrome[2315877]: time="2024-01-21T20:54:23+01:00" level=error msg="Could not set the position in track" error="mpv error: property unavailable" offset=4 track="Name: file.mp3, Socket: /tmp/mpv-ctrl-78a46eb2fb2b3094e09ce01b380a6ab0.socket"
Jan 21 20:54:23 myservice navidrome[2315877]: time="2024-01-21T20:54:23+01:00" level=error msg="error setting position" error="mpv error: property unavailable" requestId=myservice/19pB3ypxxD-001499 username=username
Jan 21 20:54:23 egon navidrome[2315877]: time="2024-01-21T20:54:23+01:00" level=error msg="Error sending quit command to mpv-ipc socket" error="trying to send command on closed mpv client"
[multiple identical messages]
Jan 21 20:54:25 egon navidrome[2315877]: time="2024-01-21T20:54:25+01:00" level=error msg="Problem getting paused status" error="trying to send command on closed mpv client" track="Name: file.mp3, Socket: /tmp/mpv-ctrl-b08c6e5b0946f2e44035c3b9b47cd6d9.socket"
Jan 21 20:54:25 egon navidrome[2315877]: time="2024-01-21T20:54:25+01:00" level=error msg="Error sending quit command to mpv-ipc socket" error="trying to send command on closed mpv client"
[multiple identical messages]
With DSub:
Jan 21 20:49:56 myservice navidrome[2315877]: time="2024-01-21T20:49:56+01:00" level=error msg="Error sending quit command to mpv-ipc socket" error="trying to send command on closed mpv client"
[multiple identical messages]
Jan 21 20:50:00 myservice navidrome[2315877]: time="2024-01-21T20:50:00+01:00" level=error msg="Problem getting paused status" error="trying to send command on closed mpv client" track="Name: file.mp3, Socket: /tmp/mpv-ctrl-9aea46747499e3dd3619df4ec41f3ec0.socket"
Jan 21 20:50:00 myservice navidrome[2315877]: time="2024-01-21T20:50:00+01:00" level=error msg="Error sending quit command to mpv-ipc socket" error="trying to send command on closed mpv client"
[multiple identical messages]
Please let me know if you need further info. I'm also open to using another Jukebox-compatible client if it works :-)
I also got the above errors. Looking at the code, shouldn't https://github.com/navidrome/navidrome/blob/61257f89d2482e563f33151a9ecd7a08b0686e09/core/playback/mpv/track.go#L156 be a continue instead of break? Maybe add some (exponential) back off / pause until the next IPC request as well?
I have to admit I don't understand the whole of the Jukebox code, and I don't use it myself, but maybe @ms140569 can chime in?
@julienlag which version of mpv is running on your box? I'm on my way to FOSDEM but will look into this once I'm back.
here, @ms140569 :
mpv --version
mpv 0.34.1 Copyright © 2000-2021 mpv/MPlayer/mplayer2 projects
built on UNKNOWN
FFmpeg library versions:
libavutil 56.70.100
libavcodec 58.134.100
libavformat 58.76.100
libswscale 5.9.100
libavfilter 7.110.100
libswresample 3.9.100
FFmpeg version: 4.4.2-0ubuntu0.22.04.1
@ms140569 upgraded mpv to version 0.37.0, the problem unfortunately remains... :-(
I have reinstalled with Ubuntu 22.04.3, Navidrome 0.51.0 (fd61b29a), and MPV 0.34.1 and I no longer see the errors that began this thread. Now I get as follows, error line bolded:
Jan 23 17:24:48 macminid navidrome[4693]: time="2024-01-23T17:24:48-05:00" level=debug msg="Executing mpv command" cmd="[/usr/bin/mpv --audio-device=auto --no-audio-display --pause /home/sean/Music/MUSIC/AIR/Moon Safari/09 New Star In The Sky (Chanson Pour.mp3 --input-ipc-server=/tmp/mpv-ctrl-472f8a4530ffe2e2dc78d303cc3d3393.socket]" Jan 23 17:24:48 macminid navidrome[4693]: time="2024-01-23T17:24:48-05:00" level=debug msg="Unpausing track" track="Name: /home/sean/Music/MUSIC/AIR/Moon Safari/09 New Star In The Sky (Chanson Pour.mp3, Socket: /tmp/mpv-ctrl-472f8a4530ffe2e2dc78d303cc3d3393.socket" Jan 23 17:24:48 macminid navidrome[4693]: time="2024-01-23T17:24:48-05:00" level=debug msg="Closing resources" track="Name: /home/sean/Music/MUSIC/AIR/Moon Safari/09 New Star In The Sky (Chanson Pour.mp3, Socket: /tmp/mpv-ctrl-472f8a4530ffe2e2dc78d303cc3d3393.socket" Jan 23 17:24:48 macminid navidrome[4693]: time="2024-01-23T17:24:48-05:00" level=error msg="Error sending quit command to mpv-ipc socket" error="trying to send command on closed mpv client" Jan 23 17:24:48 macminid navidrome[4693]: time="2024-01-23T17:24:48-05:00" level=debug msg="Removing socketfile" socketfile=/tmp/mpv-ctrl-472f8a4530ffe2e2dc78d303cc3d3393.socket Jan 23 17:24:48 macminid navidrome[4693]: time="2024-01-23T17:24:48-05:00" level=debug msg="Executing mpv command" cmd="[/usr/bin/mpv --audio-device=auto --no-audio-display --pause /home/sean/Music/MUSIC/AIR/Moon Safari/10 Le Voyage De Penelope.mp3 --input-ipc-server=/tmp/mpv-ctrl-0d2fd419544fa6c78ef73ab065282dd1.socket]" Jan 23 17:24:48 macminid navidrome[4693]: time="2024-01-23T17:24:48-05:00" level=debug msg="Unpausing track" track="Name: /home/sean/Music/MUSIC/AIR/Moon Safari/10 Le Voyage De Penelope.mp3, Socket: /tmp/mpv-ctrl-0d2fd419544fa6c78ef73ab065282dd1.socket" Jan 23 17:24:49 macminid navidrome[4693]: time="2024-01-23T17:24:49-05:00" level=debug msg="Closing resources" track="Name: /home/sean/Music/MUSIC/AIR/Moon Safari/10 Le Voyage De Penelope.mp3, Socket: /tmp/mpv-ctrl-0d2fd419544fa6c78ef73ab065282dd1.socket" Jan 23 17:24:49 macminid navidrome[4693]: time="2024-01-23T17:24:49-05:00" level=error msg="Error sending quit command to mpv-ipc socket" error="trying to send command on closed mpv client" Jan 23 17:24:49 macminid navidrome[4693]: time="2024-01-23T17:24:49-05:00" level=debug msg="Removing socketfile" socketfile=/tmp/mpv-ctrl-0d2fd419544fa6c78ef73ab065282dd1.socket
On Sun, 4 Feb 2024 at 16:08, Matthias Schmidt @.***> wrote:
@julienlag https://github.com/julienlag Do you see the control(socket)files created?
— Reply to this email directly, view it on GitHub https://github.com/navidrome/navidrome/issues/2771#issuecomment-1925914658, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABYQRPL6FE4ISD7ZSMIAAELYR72FDAVCNFSM6AAAAABBQOVKBSVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSMRVHEYTINRVHA . You are receiving this because you commented.Message ID: @.***>
As an update, if run this command:
/usr/bin/mpv --audio-device=auto --no-audio-display "/home/sean/Music/MUSIC/AIR/Moon Safari/09 New Star In The Sky (Chanson Pour.mp3" --input-ipc-server=/tmp/mpv-ctrl-472f8a4530ffe2e2dc78d303cc3d3393.socket
The socket is created and there are no errors.
On Sun, 4 Feb 2024 at 16:55, Sean Hurley @.***> wrote:
I have reinstalled with Ubuntu 22.04.3, Navidrome 0.51.0 (fd61b29a), and MPV 0.34.1 and I no longer see the errors that began this thread. Now I get as follows, error line bolded:
Jan 23 17:24:48 macminid navidrome[4693]: time="2024-01-23T17:24:48-05:00" level=debug msg="Executing mpv command" cmd="[/usr/bin/mpv --audio-device=auto --no-audio-display --pause /home/sean/Music/MUSIC/AIR/Moon Safari/09 New Star In The Sky (Chanson Pour.mp3 --input-ipc-server=/tmp/mpv-ctrl-472f8a4530ffe2e2dc78d303cc3d3393.socket]" Jan 23 17:24:48 macminid navidrome[4693]: time="2024-01-23T17:24:48-05:00" level=debug msg="Unpausing track" track="Name: /home/sean/Music/MUSIC/AIR/Moon Safari/09 New Star In The Sky (Chanson Pour.mp3, Socket: /tmp/mpv-ctrl-472f8a4530ffe2e2dc78d303cc3d3393.socket" Jan 23 17:24:48 macminid navidrome[4693]: time="2024-01-23T17:24:48-05:00" level=debug msg="Closing resources" track="Name: /home/sean/Music/MUSIC/AIR/Moon Safari/09 New Star In The Sky (Chanson Pour.mp3, Socket: /tmp/mpv-ctrl-472f8a4530ffe2e2dc78d303cc3d3393.socket" Jan 23 17:24:48 macminid navidrome[4693]: time="2024-01-23T17:24:48-05:00" level=error msg="Error sending quit command to mpv-ipc socket" error="trying to send command on closed mpv client" Jan 23 17:24:48 macminid navidrome[4693]: time="2024-01-23T17:24:48-05:00" level=debug msg="Removing socketfile" socketfile=/tmp/mpv-ctrl-472f8a4530ffe2e2dc78d303cc3d3393.socket Jan 23 17:24:48 macminid navidrome[4693]: time="2024-01-23T17:24:48-05:00" level=debug msg="Executing mpv command" cmd="[/usr/bin/mpv --audio-device=auto --no-audio-display --pause /home/sean/Music/MUSIC/AIR/Moon Safari/10 Le Voyage De Penelope.mp3 --input-ipc-server=/tmp/mpv-ctrl-0d2fd419544fa6c78ef73ab065282dd1.socket]" Jan 23 17:24:48 macminid navidrome[4693]: time="2024-01-23T17:24:48-05:00" level=debug msg="Unpausing track" track="Name: /home/sean/Music/MUSIC/AIR/Moon Safari/10 Le Voyage De Penelope.mp3, Socket: /tmp/mpv-ctrl-0d2fd419544fa6c78ef73ab065282dd1.socket" Jan 23 17:24:49 macminid navidrome[4693]: time="2024-01-23T17:24:49-05:00" level=debug msg="Closing resources" track="Name: /home/sean/Music/MUSIC/AIR/Moon Safari/10 Le Voyage De Penelope.mp3, Socket: /tmp/mpv-ctrl-0d2fd419544fa6c78ef73ab065282dd1.socket" Jan 23 17:24:49 macminid navidrome[4693]: time="2024-01-23T17:24:49-05:00" level=error msg="Error sending quit command to mpv-ipc socket" error="trying to send command on closed mpv client" Jan 23 17:24:49 macminid navidrome[4693]: time="2024-01-23T17:24:49-05:00" level=debug msg="Removing socketfile" socketfile=/tmp/mpv-ctrl-0d2fd419544fa6c78ef73ab065282dd1.socket
On Sun, 4 Feb 2024 at 16:08, Matthias Schmidt @.***> wrote:
@julienlag https://github.com/julienlag Do you see the control(socket)files created?
— Reply to this email directly, view it on GitHub https://github.com/navidrome/navidrome/issues/2771#issuecomment-1925914658, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABYQRPL6FE4ISD7ZSMIAAELYR72FDAVCNFSM6AAAAABBQOVKBSVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSMRVHEYTINRVHA . You are receiving this because you commented.Message ID: @.***>
Yeah this just looks like needing to quote the filename in the cmd string when Navidrome calls out to mpv
Yeah this just looks like needing to quote the filename in the cmd string when Navidrome calls out to mpv
This may be correct. When I run the command manually with quotations around the string it does work. I will give it a try. Although, honestly, at this time I use bluetooth and it all works quite nicely.
Yeah this just looks like needing to quote the filename in the cmd string when Navidrome calls out to mpv
I don't know what is the issue, but I'm pretty sure that is not the case. This is just how array of strings are displayed in the logs. I an assure you that the filename is only one argument and is not split by spaces. This is the same way it works for ffmpeg for both importing and transcoding.
The quotes in @cyberfarer command is for bash/zsh to consider the filename one argument, but it is not necessary when calling it out with Go's exec.Command
I just checked my Linux test instance and I am able to play songs with spaces in the path without issues. See the log:
DEBU[0054] Executing mpv command cmd="[/usr/bin/mpv --audio-device=auto --no-audio-display --pause music/My latin way/VOODOOCUTS - My latin way - 01 Mi amor.mp3 --input-ipc-server=/tmp/mpv-ctrl-9078e11172ab0d743d3bc20fd3cf33c4.socket]"
I found my way here after posting about my jukebox trouble on Reddit ( https://www.reddit.com/r/navidrome/comments/1ar4sc8/error_with_jukebox_mode_and_music_files_with/ )
For me, the quotes seem to have fixed the error when calling MPV to play a file.
Can you explain that? Do you mean by manually running the command or did you amend the code?
On Fri, Feb 16, 2024, 5:04 p.m. Michael DeVivo @.***> wrote:
I found my way here after posting about my jukebox trouble on Reddit ( https://www.reddit.com/r/navidrome/comments/1ar4sc8/error_with_jukebox_mode_and_music_files_with/ )
For me, the quotes seem to have fixed the error when calling MPV to play a file.
— Reply to this email directly, view it on GitHub https://github.com/navidrome/navidrome/issues/2771#issuecomment-1949400083, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABYQRPLNDHQHGXC7U67JEPDYT7JYTAVCNFSM6AAAAABBQOVKBSVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSNBZGQYDAMBYGM . You are receiving this because you were mentioned.Message ID: @.***>
I also got the above errors. Looking at the code, shouldn't
https://github.com/navidrome/navidrome/blob/61257f89d2482e563f33151a9ecd7a08b0686e09/core/playback/mpv/track.go#L156 be a continue instead of break? Maybe add some (exponential) back off / pause until the next IPC request as well?
I'm also running navidrome 0.51.0 with mpv 0.32.0 on a Raspberry Pi 4 Model B Rev 1.5 and I'm getting the same errors I tried to follow the log and code, I arrived to the same conclusion.
Executing the mpv command doesn't raise any error and the track is then unpause.
Looking at the Start function, on device.go, the function is calling getStatus() https://github.com/navidrome/navidrome/blob/6d253225de088e27f9a191d6bcedcb2e68b123fa/core/playback/device.go#L103
getStatus() call the pd.ActiveTrack.Position() function. https://github.com/navidrome/navidrome/blob/6d253225de088e27f9a191d6bcedcb2e68b123fa/core/playback/device.go#L48
Position() on track.go is the one returning the "mpv error: property unavailable" but never retry due to the break. https://github.com/navidrome/navidrome/blob/6d253225de088e27f9a191d6bcedcb2e68b123fa/core/playback/mpv/track.go#L146
From the player point of view (DSub), the song never progress and stay at 0:00. Hope this feedback is helpful
@mpdevivo
I found my way here after posting about my jukebox trouble on Reddit ( https://www.reddit.com/r/navidrome/comments/1ar4sc8/error_with_jukebox_mode_and_music_files_with/ )
For me, the quotes seem to have fixed the error when calling MPV to play a file.
If you need to call mpv
(or any other command for that matter) from the command line, so then yes, you need to put quotes around filepaths with spaces. But that's NOT the case, as Navidrome is NOT using the shell to execute the command. The fact that you see the command in the logs without quotes does NOT means the filepath is split when calling mpv
. This is just the way Navidrome logs array of strings, and the fact that it looks like a valid command line, it is not meant to be.
So no, that's not the issue. And you can see in my previous comment that I am able to play files with spaces on a Linux machine without this issue. What we have here is something else.
But that's not your fault, the log format is really misleading. Maybe a better way to represent the command to be executed is something like this:
Executing mpv command cmd="['/usr/bin/mpv','--audio-device=alsa/sysdefault:CARD=sndrpihifiberry', '--no-audio-display', '--pause', '/media/volumio/MP3/Various/00s Miscellaneous/01 Tubthumper.mp3', '--input-ipc-server=/tmp/mpv-ctrl-7dcd7ec4fc01af918a1752c863c73709.socket']"
This is the actual command being launched by Navidrome. I'll probably change the logs to this format above to stop the confusion.
Do you mean by manually running the command or did you amend the code?
@cyberfarer there's nothing to amend in the code regarding quotes, this is not the issue.
@thulard Thanks for the detailed analysis. Hopefully @ms140569 will be able to get back to this sooner than later.
@cyberfarer, yes I ran it manually in a command window. I found the error in the logs, extracted the command and ran it in a command window, receiving an error. When I added the quotes it worked.
@deluan , thank you for the explanation!
I experience the same issue with playing files; trying to cast internet radio via DSub gives me a different error:
Feb 21 17:19:33 raspberrypi navidrome[11380]: time="2024-02-21T17:19:33Z" level=error msg="internal error: current song index out of bounds" idx=0 length=0
Streaming internet radio with mpg123 works just fine.
@ms140569 Have you had the time to look at this?
I experience the same issue with playing files; trying to cast internet radio via DSub gives me a different error:
Feb 21 17:19:33 raspberrypi navidrome[11380]: time="2024-02-21T17:19:33Z" level=error msg="internal error: current song index out of bounds" idx=0 length=0
Streaming internet radio with mpg123 works just fine.
Can confirm the problem with radios, I have only aac and flac streams and none of them work. Latest MPV. Normal, local jukebox mode [via DSUB] is also wonky, you have to pause/unpause to get it to play. Ultrasonic seems to behave better when Jukebox is set as default in config.
I was also hitting "Hitting end-of-stream, signalling on channel" on Linux (Raspbian 11) with navidrome 0.52.0 (92a98cd5) and mpv 0.37, using iSub as the client.
When starting navidrome from the command-line, jukebox worked fine:
cd /var/lib/navidrome; /opt/navidrome/navidrome --configfile "/var/lib/navidrome/navidrome.toml"
...so I figured it was due to extra security options in the systemd unit. I commented out those and it works now as a service as well:
# DevicePolicy=closed
# NoNewPrivileges=yes
# PrivateTmp=yes
# PrivateUsers=yes
# ProtectControlGroups=yes
# ProtectKernelModules=yes
# ProtectKernelTunables=yes
# RestrictAddressFamilies=AF_UNIX AF_INET AF_INET6
# RestrictNamespaces=yes
# RestrictRealtime=yes
# SystemCallFilter=~@clock @debug @module @mount @obsolete @reboot @setuid @swap
# ReadWritePaths=/var/lib/navidrome
# ...
# ProtectSystem=full
Didn't have the time to debug this further; I ran under with User=nickolay, Group=nickolay, MusicFolder="/home/nickolay/Music. (I didn't have success with play:Sub even after iSub started working, anyone else got it working?)
The failing logs were:
level=debug msg="Executing mpv command" cmd="[/usr/bin/mpv --audio-device=auto --no-audio-display --pause /home/nickolay/Music/children-songs/xxx-xxxxxxx-xxxxx.mp3 --input-ipc-server=/tmp/mpv-ctrl-ed38f1d6-3810-48dd-bb10-b35897ece8a1.socket]"
level=debug msg="Socket found" retries=2 waitTime=201ms
level=debug msg="Setting position" offset=0 track="Name: /home/nickolay/Music/children-songs/xxx-xxxxxxx-xxxxx.mp3, Socket: /tmp/mpv-ctrl-ed38f1d6-3810-48dd-bb10-b35897ece8a1.socket"
level=debug msg="Got mpv error, retrying..." error="mpv error: property unavailable" retries=1
level=debug msg="No position difference, skipping operation" track="Name: /home/nickolay/Music/children-songs/xxx-xxxxxxx-xxxxx.mp3, Socket: /tmp/mpv-ctrl-ed38f1d6-3810-48dd-bb10-b35897ece8a1.socket"
level=info msg="Hitting end-of-stream, signalling on channel"
level=error msg="Error getting position in track" error="trying to send command on closed mpv client" track="Name: /home/nickolay/Music/children-songs/xxx-xxxxxxx-xxxxx.mp3, Socket: /tmp/mpv-ctrl-ed38f1d6-3810-48dd-bb10-b35897ece8a1.socket"
level=debug msg="Checking if track is playing" track="Name: /home/nickolay/Music/children-songs/xxx-xxxxxxx-xxxxx.mp3, Socket: /tmp/mpv-ctrl-ed38f1d6-3810-48dd-bb10-b35897ece8a1.socket"
level=error msg="Problem getting paused status" error="trying to send command on closed mpv client" track="Name: /home/nickolay/Music/children-songs/xxx-xxxxxxx-xxxxx.mp3, Socket: /tmp/mpv-ctrl-ed38f1d6-3810-48dd-bb10-b35897ece8a1.socket"
level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=argon/yBUWuPtrnN-000013 status=OK
On Wed, May 1, 2024 at 11:16 PM Nickolay @.***> wrote:
I was also hitting "Hitting end-of-stream, signalling on channel" on Linux (Raspbian 11) with navidrome 0.52.0 (92a98cd https://github.com/navidrome/navidrome/commit/92a98cd558dd7f05f65fea4830a661aa47abacf9) and mpv 0.37, using iSub as the client.
When starting navidrome from the command-line, jukebox worked fine:
cd /var/lib/navidrome; /opt/navidrome/navidrome --configfile "/var/lib/navidrome/navidrome.toml"
jukebox still doesn't work for me under this setup, unfortunately...
...so I figured it was due to extra security options in the systemd unit https://www.navidrome.org/docs/installation/linux/#create-a-systemd-unit. I commented out those and it works now as a service as well:
DevicePolicy=closed
NoNewPrivileges=yes
PrivateTmp=yes
PrivateUsers=yes
ProtectControlGroups=yes
ProtectKernelModules=yes
ProtectKernelTunables=yes
RestrictAddressFamilies=AF_UNIX AF_INET AF_INET6
RestrictNamespaces=yes
RestrictRealtime=yes
@.*** @debug @module @mount @obsolete @reboot @setuid @swap
ReadWritePaths=/var/lib/navidrome
...
ProtectSystem=full
Didn't have the time to debug this further; I ran under with User=nickolay, Group=nickolay, MusicFolder="/home/nickolay/Music. (I didn't have success with play:Sub even after iSub started working, anyone else got it working?)
The failing logs were:
level=debug msg="Executing mpv command" cmd="[/usr/bin/mpv --audio-device=auto --no-audio-display --pause /home/nickolay/Music/children-songs/xxx-xxxxxxx-xxxxx.mp3 --input-ipc-server=/tmp/mpv-ctrl-ed38f1d6-3810-48dd-bb10-b35897ece8a1.socket]" level=debug msg="Socket found" retries=2 waitTime=201ms level=debug msg="Setting position" offset=0 track="Name: /home/nickolay/Music/children-songs/xxx-xxxxxxx-xxxxx.mp3, Socket: /tmp/mpv-ctrl-ed38f1d6-3810-48dd-bb10-b35897ece8a1.socket" level=debug msg="Got mpv error, retrying..." error="mpv error: property unavailable" retries=1 level=debug msg="No position difference, skipping operation" track="Name: /home/nickolay/Music/children-songs/xxx-xxxxxxx-xxxxx.mp3, Socket: /tmp/mpv-ctrl-ed38f1d6-3810-48dd-bb10-b35897ece8a1.socket" level=info msg="Hitting end-of-stream, signalling on channel" level=error msg="Error getting position in track" error="trying to send command on closed mpv client" track="Name: /home/nickolay/Music/children-songs/xxx-xxxxxxx-xxxxx.mp3, Socket: /tmp/mpv-ctrl-ed38f1d6-3810-48dd-bb10-b35897ece8a1.socket" level=debug msg="Checking if track is playing" track="Name: /home/nickolay/Music/children-songs/xxx-xxxxxxx-xxxxx.mp3, Socket: /tmp/mpv-ctrl-ed38f1d6-3810-48dd-bb10-b35897ece8a1.socket" level=error msg="Problem getting paused status" error="trying to send command on closed mpv client" track="Name: /home/nickolay/Music/children-songs/xxx-xxxxxxx-xxxxx.mp3, Socket: /tmp/mpv-ctrl-ed38f1d6-3810-48dd-bb10-b35897ece8a1.socket" level=debug msg="API: Successful response" endpoint=/rest/jukeboxControl.view requestId=argon/yBUWuPtrnN-000013 status=OK
— Reply to this email directly, view it on GitHub https://github.com/navidrome/navidrome/issues/2771#issuecomment-2089152259, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABGBZAMFN2Y7YZWMLMFWCMLZAFLSPAVCNFSM6AAAAABBQOVKBSVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDAOBZGE2TEMRVHE . You are receiving this because you were mentioned.Message ID: @.***>
@julienlag Have you added your user to the "audio" group? Here's my service file which works on rpi4:
`[Unit] Description=Navidrome Music Server and Streamer compatible with Subsonic/Airsonic After=remote-fs.target network.target AssertPathExists=/var/lib/navidrome
[Install] WantedBy=multi-user.target
[Service] User=schmidtm Group=schmidtm Type=simple ExecStart=/home/schmidtm/prj/navidrome/fork/navidrome/navidrome --configfile "/var/lib/navidrome/navidrome.toml" WorkingDirectory=/var/lib/navidrome Restart=on-failure`
I have my user in the audio group and as the service and it does not work. Exact same issue as before.
On Sun, 12 May 2024 at 03:50, Matthias Schmidt @.***> wrote:
@julienlag https://github.com/julienlag Have you added your user to the "audio" group? Here's my service file which works on rpi4:
`[Unit] Description=Navidrome Music Server and Streamer compatible with Subsonic/Airsonic After=remote-fs.target network.target AssertPathExists=/var/lib/navidrome
[Install] WantedBy=multi-user.target
[Service] User=schmidtm Group=schmidtm Type=simple ExecStart=/home/schmidtm/prj/navidrome/fork/navidrome/navidrome --configfile "/var/lib/navidrome/navidrome.toml" WorkingDirectory=/var/lib/navidrome Restart=on-failure`
— Reply to this email directly, view it on GitHub https://github.com/navidrome/navidrome/issues/2771#issuecomment-2106154928, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABYQRPI3HZSJLKUGHAP4UTTZB4NNDAVCNFSM6AAAAABBQOVKBSVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDCMBWGE2TIOJSHA . You are receiving this because you were mentioned.Message ID: @.***>
@julienlag Have you added your user to the "audio" group? Here's my service file which works on rpi4:
`[Unit] Description=Navidrome Music Server and Streamer compatible with Subsonic/Airsonic After=remote-fs.target network.target AssertPathExists=/var/lib/navidrome
[Install] WantedBy=multi-user.target
[Service] User=schmidtm Group=schmidtm Type=simple ExecStart=/home/schmidtm/prj/navidrome/fork/navidrome/navidrome --configfile "/var/lib/navidrome/navidrome.toml" WorkingDirectory=/var/lib/navidrome Restart=on-failure`
thanks, but none of this worked for me
@cyberfarer @julienlag
Are you both trying to play static files? I'm loosing the overview which one is facing which problem. We might deal with multiple problems. I know this is already going on for some time, but could you guys please paste the relevant/last part of the logfile showing the error? Bear with me, Matthias.
@cyberfarer @julienlag
Are you both trying to play static files? I'm loosing the overview which one is facing which problem. We might deal with multiple problems. I know this is already going on for some time, but could you guys please paste the relevant/last part of the logfile showing the error? Bear with me, Matthias.
thanks @ms140569 for looking into this. You're right, this thread is getting difficult to follow In summary: I'm the original issue poster, you can find my report above. Since the original report I have upgraded MPV to v.0.38.0 and navidrome to v0.52.5, tried all suggestions made by others in this thread, without success (i.e. I'm seeing the same MPV-related error messages in the log as originally reported). Happy to provide more details
Hi, if by "static" you mean audio files residing on my computer, yes. Here are the relevant logs:
May 13 22:44:23 MacMini navidrome[120089]: time="2024-05-13T22:44:23-04:00"
level=debug msg="Loading track" mediaType=audio/flac
trackPath="/home/sean/Music/OneRepublic/Native/OneRepublic-Native-If I Lose
Myself (1).flac"
May 13 22:44:23 MacMini navidrome[120089]: time="2024-05-13T22:44:23-04:00"
level=debug msg="Executing mpv command" cmd="[/usr/bin/mpv
--audio-device=auto --no-audio-display --pause
/home/sean/Music/OneRepublic/Native/OneRepublic-Native-If I Lose Myself
(1).flac
--input-ipc-server=/tmp/mpv-ctrl-db1c4d698752c85382963b6e2f719d74.socket]"
May 13 22:44:23 MacMini navidrome[120089]: time="2024-05-13T22:44:23-04:00"
level=debug msg="Socket found" retries=1 waitTime=100.3ms
May 13 22:44:23 MacMini navidrome[120089]: time="2024-05-13T22:44:23-04:00"
level=debug msg="Unpausing track" track="Name:
/home/sean/Music/OneRepublic/Native/OneRepublic-Native-If I Lose Myself
(1).flac, Socket: /tmp/mpv-ctrl-db1c4d698752c85382963b6e2f719d74.socket"
May 13 22:44:23 MacMini navidrome[120089]: time="2024-05-13T22:44:23-04:00"
level=debug msg="Got mpv error, retrying..." error="mpv error: property
unavailable" retries=1
May 13 22:44:23 MacMini navidrome[120089]: time="2024-05-13T22:44:23-04:00"
level=debug msg="Checking if track is playing" track="Name:
/home/sean/Music/OneRepublic/Native/OneRepublic-Native-If I Lose Myself
(1).flac, Socket: /tmp/mpv-ctrl-db1c4d698752c85382963b6e2f719d74.socket"
May 13 22:44:23 MacMini navidrome[120089]: time="2024-05-13T22:44:23-04:00"
level=debug msg="API: Successful response"
endpoint=/rest/jukeboxControl.view requestId=MacMini/edA1En4OfP-000360
status=OK username=sean
May 13 22:44:23 MacMini navidrome[120089]: time="2024-05-13T22:44:23-04:00"
level=debug msg="HTTP: GET
http://192.168.68.124:4533/rest/jukeboxControl.view?u=sean&s=[REDACTED]&t=[REDACTED]&v=1.2.0&c=DSub&action=start"
elapsedTime=120.7ms httpStatus=200 remoteAddr="192.168.68.100:52154"
requestId=MacMini/edA1En4OfP-000360 responseSize=248 userAgent=DSub
May 13 22:44:23 MacMini navidrome[120089]: time="2024-05-13T22:44:23-04:00"
level=info msg="Hitting end-of-stream, signalling on channel"
May 13 22:44:23 MacMini navidrome[120089]: time="2024-05-13T22:44:23-04:00"
level=debug msg="Track switching detected"
May 13 22:44:23 MacMini navidrome[120089]: time="2024-05-13T22:44:23-04:00"
level=debug msg="Closing resources" track="Name:
/home/sean/Music/OneRepublic/Native/OneRepublic-Native-If I Lose Myself
(1).flac, Socket: /tmp/mpv-ctrl-db1c4d698752c85382963b6e2f719d74.socket"
May 13 22:44:23 MacMini navidrome[120089]: time="2024-05-13T22:44:23-04:00"
level=debug msg="sending shutdown command"
May 13 22:44:23 MacMini navidrome[120089]: time="2024-05-13T22:44:23-04:00"
level=error msg="Error sending quit command to mpv-ipc socket"
error="trying to send command on closed mpv client"
May 13 22:44:23 MacMini navidrome[120089]: time="2024-05-13T22:44:23-04:00"
level=debug msg="cancelling executor"
May 13 22:44:23 MacMini navidrome[120089]: time="2024-05-13T22:44:23-04:00"
level=debug msg="Removing socketfile"
socketfile=/tmp/mpv-ctrl-db1c4d698752c85382963b6e2f719d74.socket
May 13 22:44:23 MacMini navidrome[120089]: time="2024-05-13T22:44:23-04:00"
level=debug msg="There is no song left in the playlist. Finish."
May 13 22:44:24 MacMini navidrome[120089]: time="2024-05-13T22:44:24-04:00"
level=debug msg="API: New request /rest/jukeboxControl.view" client=DSub
requestId=MacMini/edA1En4OfP-000361 username=sean version=1.2.0
May 13 22:44:24 MacMini navidrome[120089]: time="2024-05-13T22:44:24-04:00"
level=debug msg="API: New request /rest/savePlayQueue.view" client=DSub
requestId=MacMini/edA1En4OfP-000362 username=sean version=1.2.0
May 13 22:44:24 MacMini navidrome[120089]: time="2024-05-13T22:44:24-04:00"
level=debug msg="Processing GetDevice" user=sean
May 13 22:44:24 MacMini navidrome[120089]: time="2024-05-13T22:44:24-04:00"
level=info msg="JukeboxControl request received" action=stop
requestId=MacMini/edA1En4OfP-000361 username=sean
May 13 22:44:24 MacMini navidrome[120089]: time="2024-05-13T22:44:24-04:00"
level=debug msg="Processing Stop action" device="Name: auto, Gain: 1.0000,
Loaded track: %!s(
On Sun, 12 May 2024 at 13:15, Matthias Schmidt @.***> wrote:
@cyberfarer https://github.com/cyberfarer @julienlag https://github.com/julienlag
Are you both trying to play static files? I'm loosing the overview which one is facing which problem. We might deal with multiple problems. I know this is already going on for some time, but could you guys please paste the relevant/last part of the logfile showing the error? Bear with me, Matthias.
— Reply to this email directly, view it on GitHub https://github.com/navidrome/navidrome/issues/2771#issuecomment-2106318414, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABYQRPNWIW3IDWCGUKK6ZQ3ZB6PT5AVCNFSM6AAAAABBQOVKBSVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDCMBWGMYTQNBRGQ . You are receiving this because you were mentioned.Message ID: @.***>
@julienlag I've a hard time to reproduce your issue. I'm using Ultrasonic as well against various versions of ND on a Rpi4.
Do I get this right: You always get the error-sequence given in the Bug-description above on the first attempt to play any file in Jukebox-Mode?
So, you always get this message:
"got the mpv error: property unavailable error, retry ..."
correct?
@julienlag I've a hard time to reproduce your issue. I'm using Ultrasonic as well against various versions of ND on a Rpi4.
Do I get this right: You always get the error-sequence given in the Bug-description above on the first attempt to play any file in Jukebox-Mode?
So, you always get this message:
"got the mpv error: property unavailable error, retry ..."
correct?
Yes, exactly!
@julienlag I've a hard time to reproduce your issue. I'm using Ultrasonic as well against various versions of ND on a Rpi4. Do I get this right: You always get the error-sequence given in the Bug-description above on the first attempt to play any file in Jukebox-Mode? So, you always get this message: "got the mpv error: property unavailable error, retry ..." correct?
Yes, exactly!
I can confirm the same behaviour on a rpi3b+
I confirm that:
Version
0.50.2 (823bef54)
Current Behavior
From Ultrasonic (Android), turning Jukebox on ends the stream immediately. See attached relevant excerpt from navidrome log. Running manually the mpv command reported on line 26 of the log works as expected. No luck either using DSub in Jukebox mode...
Expected Behavior
Jukebox mode should work correctly
Steps To Reproduce
I followed official installation/setup instructions carefully
Environment
How Navidrome is installed?
Binary (from downloads page)
Configuration
Relevant log output
Anything else?
No response
Code of Conduct