Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

Stuttering when pushing properties data to SnapServer through a plugin #1351

Open
torzdf opened this issue Feb 15, 2025 · 6 comments
Open

Stuttering when pushing properties data to SnapServer through a plugin #1351

torzdf opened this issue Feb 15, 2025 · 6 comments

Comments

@torzdf
Copy link

torzdf commented Feb 15, 2025

First up, thanks for this awesome software!

Now, I'm not sure if what I have here is a bug, or if it is user error, probably the latter

I am currently working on a meta plugin (which I intend to PR to the project, for you to decide to use or reject, but that is a different conversation).

I have the plugin pretty much working how I want, but have hit an issue. Whenever Plugin.Stream.Player.Properties is sent to Snapserver a noticeable stutter occurs. Specifically, I see a high onResync value then 2 very noticeable stutters after this in the audio stream.

To better demonstrate, I have put together a short video. Top window is the output from Snapserver. Bottom window is the tail of the plugin's debug log (I have inserted an info jsonrpc log message so that Snapserver shows when it receives the data. This is not part of the plugin, it is just for debugging here. I can confirm that this log line has no impact on the issue):

https://www.youtube.com/watch?v=BVve-wI6Tcg

The data here is being sent every 10 seconds (again, just for testing purposes. It makes no difference if this is 1 second, or 10 minutes, the stutter still occurs). The bottom debug log shows the exact data that is being sent to Snapserver.

Am I missing something obvious here? Is the plugin blocking Snapserver in some way? It seems unlikely, but I can't rule it out yet.

It is probably worth adding, that running the query on the backend, but not sending the data to Snapserver does not cause the stutter, so I have ruled out issues with the source.
@badaix
Copy link
Owner

badaix commented Feb 17, 2025

I've never observed such an issue, I'm using meta_mopidy.py without any issues.
I added a simple example script in the auth branch, that will change the album art and track title if you press previous or next. Can you test if your problem also occurs with this script?

@torzdf
Copy link
Author

torzdf commented Feb 18, 2025

Thanks for getting back to me. It's good to know that the issue is my end somewhere, so will hopefully be resolvable (tbh, I thought that someone else would have found this if it was an issue with SnapServer, but wanted to be sure before I spent any more time trying to debug this).

I'll get Modipy installed when I have a bit of free time and get back to you.

@badaix
Copy link
Owner

badaix commented Feb 18, 2025

The example.py script has no dependencies, and does not require mpd. You can use it straight away for testing.

@torzdf
Copy link
Author

torzdf commented Feb 18, 2025 •
edited
Loading

It does still stutter with the example script, yes:

Info Log 
2025-02-18 13-22-27.794 [Info] (PcmStream) State changed: mpd, state: idle => playing
2025-02-18 13-22-27.794 [Info] (Server) onStateChanged (mpd): playing
2025-02-18 13-22-27.794 [Info] (ControlServer) Removing 1 inactive session(s), active sessions: 6
2025-02-18 13-22-29.480 [Info] (Server) onResync (mpd): 105.985 ms
2025-02-18 13-22-55.442 [Info] (ControlRequest) Stream.Control id: mpd, command: "next", params: ""
2025-02-18 13-22-55.442 [Info] (Script) Sending request: {"id":1,"jsonrpc":"2.0","method":"Plugin.Stream.Player.Control","params":{"command":"next"}}
2025-02-18 13-22-55.444 [Info] (ControlServer) Removing 1 inactive session(s), active sessions: 5
2025-02-18 13-22-55.444 [Info] (Script) Response: {"id":1,"jsonrpc":"2.0","result":"ok"}, id: 1
2025-02-18 13-22-57.557 [Info] (Server) onResync (mpd): 76.6241 ms
2025-02-18 13-23-06.219 [Info] (ControlRequest) Stream.Control id: mpd, command: "next", params: ""
2025-02-18 13-23-06.219 [Info] (Script) Sending request: {"id":2,"jsonrpc":"2.0","method":"Plugin.Stream.Player.Control","params":{"command":"next"}}
2025-02-18 13-23-06.221 [Info] (Script) Response: {"id":2,"jsonrpc":"2.0","result":"ok"}, id: 2
2025-02-18 13-23-08.374 [Info] (Server) onResync (mpd): 116.939 ms
2025-02-18 13-23-22.836 [Info] (ControlRequest) Stream.Control id: mpd, command: "next", params: ""
2025-02-18 13-23-22.836 [Info] (Script) Sending request: {"id":3,"jsonrpc":"2.0","method":"Plugin.Stream.Player.Control","params":{"command":"next"}}
2025-02-18 13-23-22.838 [Info] (Script) Response: {"id":3,"jsonrpc":"2.0","result":"ok"}, id: 3
2025-02-18 13-23-24.975 [Info] (Server) onResync (mpd): 100.508 ms
2025-02-18 13-23-30.926 [Info] (ControlRequest) Stream.Control id: mpd, command: "previous", params: ""
2025-02-18 13-23-30.926 [Info] (Script) Sending request: {"id":4,"jsonrpc":"2.0","method":"Plugin.Stream.Player.Control","params":{"command":"previous"}}
2025-02-18 13-23-30.928 [Info] (Script) Response: {"id":4,"jsonrpc":"2.0","result":"ok"}, id: 4
2025-02-18 13-23-33.042 [Info] (Server) onResync (mpd): 66.7589 ms
2025-02-18 13-23-36.611 [Info] (ControlRequest) Stream.Control id: mpd, command: "next", params: ""
2025-02-18 13-23-36.611 [Info] (Script) Sending request: {"id":5,"jsonrpc":"2.0","method":"Plugin.Stream.Player.Control","params":{"command":"next"}}
2025-02-18 13-23-36.613 [Info] (Script) Response: {"id":5,"jsonrpc":"2.0","result":"ok"}, id: 5
2025-02-18 13-23-38.726 [Info] (Server) onResync (mpd): 83.6598 ms
2025-02-18 13-23-43.563 [Info] (ControlRequest) Stream.Control id: mpd, command: "next", params: ""
2025-02-18 13-23-43.563 [Info] (Script) Sending request: {"id":6,"jsonrpc":"2.0","method":"Plugin.Stream.Player.Control","params":{"command":"next"}}
2025-02-18 13-23-43.565 [Info] (Script) Response: {"id":6,"jsonrpc":"2.0","result":"ok"}, id: 6
2025-02-18 13-23-45.676 [Info] (Server) onResync (mpd): 69.9774 ms
2025-02-18 13-23-47.638 [Info] (ControlRequest) Stream.Control id: mpd, command: "previous", params: ""
2025-02-18 13-23-47.638 [Info] (Script) Sending request: {"id":7,"jsonrpc":"2.0","method":"Plugin.Stream.Player.Control","params":{"command":"previous"}}
2025-02-18 13-23-47.640 [Info] (Script) Response: {"id":7,"jsonrpc":"2.0","result":"ok"}, id: 7
2025-02-18 13-23-49.760 [Info] (Server) onResync (mpd): 83.2586 ms
2025-02-18 13-23-54.298 [Info] (ControlRequest) Stream.Control id: mpd, command: "next", params: ""
2025-02-18 13-23-54.298 [Info] (Script) Sending request: {"id":8,"jsonrpc":"2.0","method":"Plugin.Stream.Player.Control","params":{"command":"next"}}
2025-02-18 13-23-54.300 [Info] (Script) Response: {"id":8,"jsonrpc":"2.0","result":"ok"}, id: 8
2025-02-18 13-23-56.418 [Info] (Server) onResync (mpd): 58.301 ms
2025-02-18 13-23-58.705 [Info] (ControlRequest) Stream.Control id: mpd, command: "pause", params: ""
2025-02-18 13-23-58.705 [Info] (Script) Sending request: {"id":9,"jsonrpc":"2.0","method":"Plugin.Stream.Player.Control","params":{"command":"pause"}}
2025-02-18 13-23-58.706 [Info] (Script) Response: {"id":9,"jsonrpc":"2.0","result":"ok"}, id: 9
2025-02-18 13-24-00.804 [Info] (Server) onResync (mpd): 65.4149 ms

This is with loglevel set to trace... Note, I removed a load of the getNextMessage/onMessageReceived from prior to the web interface coming up, and pressing play, to remove log spam:

Trace Log 
25-02-18 13-34-30.415 [Info] (Snapserver) Version 0.31.0, revision cf2be071
2025-02-18 13-34-30.416 [Info] (Snapserver) Stream plugin directory: "/usr/share/snapserver/plug-ins"
2025-02-18 13-34-30.416 [Info] (Snapserver) Adding source: pipe:///tmp/snapfifo?name=mpd&controlscript=/home/users/matt/example.py
2025-02-18 13-34-30.418 [Notice] (init) Settings file: "/home/users/matt/.config/snapserver/server.json"
2025-02-18 13-34-30.426 [Info] (Avahi) Adding service 'Snapcast'
2025-02-18 13-34-30.438 [Debug] (StreamUri) StreamUri: pipe:///tmp/snapfifo?name=mpd&controlscript=/home/users/matt/example.py
2025-02-18 13-34-30.438 [Trace] (StreamUri) scheme: 'pipe', tmp: '///tmp/snapfifo?name=mpd&controlscript=/home/users/matt/example.py'
2025-02-18 13-34-30.438 [Trace] (StreamUri) host: '', tmp: '/tmp/snapfifo?name=mpd&controlscript=/home/users/matt/example.py', path: '/tmp/snapfifo'
2025-02-18 13-34-30.438 [Trace] (StreamUri) path: '/tmp/snapfifo', tmp: 'name=mpd&controlscript=/home/users/matt/example.py', query: 'name=mpd&controlscript=/home/users/matt/example.py'
2025-02-18 13-34-30.438 [Debug] (StreamUri) StreamUri.toString: pipe:///tmp/snapfifo?controlscript=/home/users/matt/example.py&name=mpd
2025-02-18 13-34-30.438 [Debug] (PcmStream) Chunk duration: 20 ms, frames: 960, size: 3840
2025-02-18 13-34-30.438 [Info] (PcmStream) PcmStream: mpd, sampleFormat: 48000:16:2
2025-02-18 13-34-30.438 [Debug] (PcmStream) Silence threshold percent: 0, silence threshold amplitude: 0
2025-02-18 13-34-30.438 [Debug] (AsioStream) Chunk duration: 20 ms, frames: 960, size: 3840
2025-02-18 13-34-30.438 [Info] (PipeStream) PipeStream mode: create
2025-02-18 13-34-30.438 [Info] (Server) Stream: {"fragment":"","host":"","path":"/tmp/snapfifo","query":{"chunk_ms":"20","codec":"flac","controlscript":"/home/users/matt/example.py","name":"mpd","sampleformat":"48000:16:2"},"raw":"pipe:///tmp/snapfifo?chunk_ms=20&codec=flac&controlscript=/home/users/matt/example.py&name=mpd&sampleformat=48000:16:2","scheme":"pipe"}
2025-02-18 13-34-30.439 [Debug] (StreamUri) StreamUri: pipe:///tmp/snapfifo?name=mpd&controlscript=/home/users/matt/example.py
2025-02-18 13-34-30.439 [Trace] (StreamUri) scheme: 'pipe', tmp: '///tmp/snapfifo?name=mpd&controlscript=/home/users/matt/example.py'
2025-02-18 13-34-30.439 [Trace] (StreamUri) host: '', tmp: '/tmp/snapfifo?name=mpd&controlscript=/home/users/matt/example.py', path: '/tmp/snapfifo'
2025-02-18 13-34-30.439 [Trace] (StreamUri) path: '/tmp/snapfifo', tmp: 'name=mpd&controlscript=/home/users/matt/example.py', query: 'name=mpd&controlscript=/home/users/matt/example.py'
2025-02-18 13-34-30.439 [Debug] (StreamUri) StreamUri.toString: pipe:///tmp/snapfifo?controlscript=/home/users/matt/example.py&name=mpd
2025-02-18 13-34-30.439 [Debug] (PcmStream) Start: mpd, type: pipe, sampleformat: 48000:16:2, codec: flac
2025-02-18 13-34-30.439 [Info] (FlacEnc) Init - compression level: 2
2025-02-18 13-34-30.439 [Debug] (Script) Starting control script: '/home/users/matt/example.py', params: '  "--stream=mpd" --snapcast-port=1780 --snapcast-host=192.168.1.10'
2025-02-18 13-34-30.442 [Trace] (PipeStream) Stream: mpd, connect to pipe: /tmp/snapfifo, fd: 13, pipe size: 65536
2025-02-18 13-34-30.442 [Info] (ControlServer) Creating TCP acceptor for address: ::, port: 1705
2025-02-18 13-34-30.442 [Info] (ControlServer) Creating HTTP acceptor for address: ::, port: 1780
2025-02-18 13-34-30.442 [Info] (StreamServer) Creating stream acceptor for address: ::, port: 1704
2025-02-18 13-34-30.442 [Info] (Snapserver) Number of threads: 4, hw threads: 12
2025-02-18 13-34-30.521 [Debug] (PcmStream) Notification method: Plugin.Stream.Player.Properties, params: {"canControl":true,"canGoNext":true,"canGoPrevious":true,"canPause":true,"canPlay":true,"canSeek":false,"loopStatus":"none","metadata":{"artData":{"data":"PHN2ZyB4bWxucz0iaHR0cDovL3d3dy53My5vcmcvMjAwMC9zdmciIHdpZHRoPSIxNDMwIiBoZWlnaHQ9IjE0MzAiIHZpZXdCb3g9IjAgMCAxMzQwLjYyNSAxMzQwLjYyNSI+PGcgdHJhbnNmb3JtPSJtYXRyaXgoMS4wMzAyIDAgMCAxLjAzMDIgMTc1LjQ5NSA4Mi43MzIpIj48Y2lyY2xlIGN4PSItNzM0LjA5MyIgY3k9IjEzMC43ODQiIHI9IjQzMS4yNSIgc3R5bGU9ImZpbGw6I2ZmYzEwNztmaWxsLW9wYWNpdHk6MTtzdHJva2Utd2lkdGg6MTAuNDgxNiIgdHJhbnNmb3JtPSJyb3RhdGUoLTEyMCkiLz48cGF0aCBmaWxsPSJub25lIiBkPSJNLTQyMi4wNjYtNDcuMzM1YTM2MC4zIDM2MC4zIDAgMCAxIDAgMzYwLjI5N00tNDY2Ljg3NS0zLjM3NWEyOTkuOTggMjk5Ljk4IDAgMCAxIDAgMjcyLjM3N00tNTE0Ljc1OCAzNS4xM2EyNDAuMTcgMjQwLjE3IDAgMCAxIDAgMTk1LjM2OCIgc3R5bGU9ImZpbGw6IzAwMDtmaWxsLW9wYWNpdHk6MDtmaWxsLXJ1bGU6ZXZlbm9kZDtzdHJva2U6I2ZmZjtzdHJva2Utd2lkdGg6MzU7c3Ryb2tlLWxpbmVjYXA6cm91bmQ7c3Ryb2tlLWxpbmVqb2luOm1pdGVyO3N0cm9rZS1taXRlcmxpbWl0OjQ7c3Ryb2tlLWRhc2hhcnJheTpub25lO3N0cm9rZS1vcGFjaXR5OjEiIHRyYW5zZm9ybT0icm90YXRlKC0xMjApIi8+PHBhdGggZD0ibTU5MS42MDUgNDA3LjA4MS0xMTQuMzU5IDk4LjkxMkgzNjkuMDEyVjYzMy4yOGgxMDYuNTkzbDExNiAxMDAuMzR6IiBzdHlsZT0iZmlsbDojYzhjOGM4O2ZpbGwtb3BhY2l0eToxO2ZpbGwtcnVsZTpldmVub2RkO3N0cm9rZTojZmZmO3N0cm9rZS13aWR0aDozMy4zMzM7c3Ryb2tlLWxpbmVjYXA6cm91bmQ7c3Ryb2tlLWxpbmVqb2luOnJvdW5kO3N0cm9rZS1taXRlcmxpbWl0OjQ7c3Ryb2tlLWRhc2hhcnJheTpub25lO3N0cm9rZS1vcGFjaXR5OjEiLz48cGF0aCBmaWxsPSJub25lIiBkPSJNNzkyLjMzNSAzOTIuMjMyYTM2MC4zIDM2MC4zIDAgMCAxIDAgMzYwLjI5N003NDcuNTk0IDQzNi4xOTJhMjk5Ljk4IDI5OS45OCAwIDAgMSAwIDI3Mi4zNzdNNjk5LjcxIDQ3NC42OTZhMjQwLjE3IDI0MC4xNyAwIDAgMSAwIDE5NS4zNjgiIHN0eWxlPSJmaWxsOiMwMDA7ZmlsbC1vcGFjaXR5OjA7ZmlsbC1ydWxlOmV2ZW5vZGQ7c3Ryb2tlOiNmZmY7c3Ryb2tlLXdpZHRoOjM1O3N0cm9rZS1saW5lY2FwOnJvdW5kO3N0cm9rZS1saW5lam9pbjptaXRlcjtzdHJva2UtbWl0ZXJsaW1pdDo0O3N0cm9rZS1kYXNoYXJyYXk6bm9uZTtzdHJva2Utb3BhY2l0eToxIi8+PHBhdGggZmlsbD0ibm9uZSIgZD0iTTU2NS43NDMtODc5LjI1NGEzNjAuMyAzNjAuMyAwIDAgMSAwIDM2MC4yOTdNNTIxLjAwMi04MzUuMjk1YTI5OS45OCAyOTkuOTggMCAwIDEgMCAyNzIuMzc4TTQ3My4xMTgtNzk2Ljc5YTI0MC4xNyAyNDAuMTcgMCAwIDEgMCAxOTUuMzY4IiBzdHlsZT0iZmlsbDojMDAwO2ZpbGwtb3BhY2l0eTowO2ZpbGwtcnVsZTpldmVub2RkO3N0cm9rZTojZmZmO3N0cm9rZS13aWR0aDozNTtzdHJva2UtbGluZWNhcDpyb3VuZDtzdHJva2UtbGluZWpvaW46bWl0ZXI7c3Ryb2tlLW1pdGVybGltaXQ6NDtzdHJva2UtZGFzaGFycmF5Om5vbmU7c3Ryb2tlLW9wYWNpdHk6MSIgdHJhbnNmb3JtPSJyb3RhdGUoMTIwKSIvPjwvZz48L3N2Zz4=","extension":"svg"},"artist":["artist"],"title":"track 1"},"mute":false,"playbackStatus":"playing","position":0,"rate":1.0,"shuffle":false,"volume":100}
2025-02-18 13-34-30.522 [Debug] (PcmStream) Received properties notification
2025-02-18 13-34-30.522 [Debug] (PcmStream) setProperties, stream: mpd, properties: {"canControl":true,"canGoNext":true,"canGoPrevious":true,"canPause":true,"canPlay":true,"canSeek":false,"loopStatus":"none","metadata":{"artData":{"data":"PHN2ZyB4bWxucz0iaHR0cDovL3d3dy53My5vcmcvMjAwMC9zdmciIHdpZHRoPSIxNDMwIiBoZWlnaHQ9IjE0MzAiIHZpZXdCb3g9IjAgMCAxMzQwLjYyNSAxMzQwLjYyNSI+PGcgdHJhbnNmb3JtPSJtYXRyaXgoMS4wMzAyIDAgMCAxLjAzMDIgMTc1LjQ5NSA4Mi43MzIpIj48Y2lyY2xlIGN4PSItNzM0LjA5MyIgY3k9IjEzMC43ODQiIHI9IjQzMS4yNSIgc3R5bGU9ImZpbGw6I2ZmYzEwNztmaWxsLW9wYWNpdHk6MTtzdHJva2Utd2lkdGg6MTAuNDgxNiIgdHJhbnNmb3JtPSJyb3RhdGUoLTEyMCkiLz48cGF0aCBmaWxsPSJub25lIiBkPSJNLTQyMi4wNjYtNDcuMzM1YTM2MC4zIDM2MC4zIDAgMCAxIDAgMzYwLjI5N00tNDY2Ljg3NS0zLjM3NWEyOTkuOTggMjk5Ljk4IDAgMCAxIDAgMjcyLjM3N00tNTE0Ljc1OCAzNS4xM2EyNDAuMTcgMjQwLjE3IDAgMCAxIDAgMTk1LjM2OCIgc3R5bGU9ImZpbGw6IzAwMDtmaWxsLW9wYWNpdHk6MDtmaWxsLXJ1bGU6ZXZlbm9kZDtzdHJva2U6I2ZmZjtzdHJva2Utd2lkdGg6MzU7c3Ryb2tlLWxpbmVjYXA6cm91bmQ7c3Ryb2tlLWxpbmVqb2luOm1pdGVyO3N0cm9rZS1taXRlcmxpbWl0OjQ7c3Ryb2tlLWRhc2hhcnJheTpub25lO3N0cm9rZS1vcGFjaXR5OjEiIHRyYW5zZm9ybT0icm90YXRlKC0xMjApIi8+PHBhdGggZD0ibTU5MS42MDUgNDA3LjA4MS0xMTQuMzU5IDk4LjkxMkgzNjkuMDEyVjYzMy4yOGgxMDYuNTkzbDExNiAxMDAuMzR6IiBzdHlsZT0iZmlsbDojYzhjOGM4O2ZpbGwtb3BhY2l0eToxO2ZpbGwtcnVsZTpldmVub2RkO3N0cm9rZTojZmZmO3N0cm9rZS13aWR0aDozMy4zMzM7c3Ryb2tlLWxpbmVjYXA6cm91bmQ7c3Ryb2tlLWxpbmVqb2luOnJvdW5kO3N0cm9rZS1taXRlcmxpbWl0OjQ7c3Ryb2tlLWRhc2hhcnJheTpub25lO3N0cm9rZS1vcGFjaXR5OjEiLz48cGF0aCBmaWxsPSJub25lIiBkPSJNNzkyLjMzNSAzOTIuMjMyYTM2MC4zIDM2MC4zIDAgMCAxIDAgMzYwLjI5N003NDcuNTk0IDQzNi4xOTJhMjk5Ljk4IDI5OS45OCAwIDAgMSAwIDI3Mi4zNzdNNjk5LjcxIDQ3NC42OTZhMjQwLjE3IDI0MC4xNyAwIDAgMSAwIDE5NS4zNjgiIHN0eWxlPSJmaWxsOiMwMDA7ZmlsbC1vcGFjaXR5OjA7ZmlsbC1ydWxlOmV2ZW5vZGQ7c3Ryb2tlOiNmZmY7c3Ryb2tlLXdpZHRoOjM1O3N0cm9rZS1saW5lY2FwOnJvdW5kO3N0cm9rZS1saW5lam9pbjptaXRlcjtzdHJva2UtbWl0ZXJsaW1pdDo0O3N0cm9rZS1kYXNoYXJyYXk6bm9uZTtzdHJva2Utb3BhY2l0eToxIi8+PHBhdGggZmlsbD0ibm9uZSIgZD0iTTU2NS43NDMtODc5LjI1NGEzNjAuMyAzNjAuMyAwIDAgMSAwIDM2MC4yOTdNNTIxLjAwMi04MzUuMjk1YTI5OS45OCAyOTkuOTggMCAwIDEgMCAyNzIuMzc4TTQ3My4xMTgtNzk2Ljc5YTI0MC4xNyAyNDAuMTcgMCAwIDEgMCAxOTUuMzY4IiBzdHlsZT0iZmlsbDojMDAwO2ZpbGwtb3BhY2l0eTowO2ZpbGwtcnVsZTpldmVub2RkO3N0cm9rZTojZmZmO3N0cm9rZS13aWR0aDozNTtzdHJva2UtbGluZWNhcDpyb3VuZDtzdHJva2UtbGluZWpvaW46bWl0ZXI7c3Ryb2tlLW1pdGVybGltaXQ6NDtzdHJva2UtZGFzaGFycmF5Om5vbmU7c3Ryb2tlLW9wYWNpdHk6MSIgdHJhbnNmb3JtPSJyb3RhdGUoMTIwKSIvPjwvZz48L3N2Zz4=","extension":"svg"},"artUrl":"http://192.168.1.10:1780/__image_cache?name=e0f65f56fe83483156c8eac243304974.svg","artist":["artist"],"title":"track 1"},"mute":false,"playbackStatus":"playing","position":0.0,"rate":1.0,"shuffle":false,"volume":100}
2025-02-18 13-34-30.523 [Debug] (Server) Properties changed, stream: mpd, properties: {
2025-02-18 13-34-30.523 [Debug] (Server)    "canControl": true,
2025-02-18 13-34-30.523 [Debug] (Server)    "canGoNext": true,
2025-02-18 13-34-30.523 [Debug] (Server)    "canGoPrevious": true,
2025-02-18 13-34-30.523 [Debug] (Server)    "canPause": true,
2025-02-18 13-34-30.523 [Debug] (Server)    "canPlay": true,
2025-02-18 13-34-30.523 [Debug] (Server)    "canSeek": false,
2025-02-18 13-34-30.523 [Debug] (Server)    "loopStatus": "none",
2025-02-18 13-34-30.523 [Debug] (Server)    "metadata": {
2025-02-18 13-34-30.523 [Debug] (Server)       "artData": {
2025-02-18 13-34-30.523 [Debug] (Server)          "data": "PHN2ZyB4bWxucz0iaHR0cDovL3d3dy53My5vcmcvMjAwMC9zdmciIHdpZHRoPSIxNDMwIiBoZWlnaHQ9IjE0MzAiIHZpZXdCb3g9IjAgMCAxMzQwLjYyNSAxMzQwLjYyNSI+PGcgdHJhbnNmb3JtPSJtYXRyaXgoMS4wMzAyIDAgMCAxLjAzMDIgMTc1LjQ5NSA4Mi43MzIpIj48Y2lyY2xlIGN4PSItNzM0LjA5MyIgY3k9IjEzMC43ODQiIHI9IjQzMS4yNSIgc3R5bGU9ImZpbGw6I2ZmYzEwNztmaWxsLW9wYWNpdHk6MTtzdHJva2Utd2lkdGg6MTAuNDgxNiIgdHJhbnNmb3JtPSJyb3RhdGUoLTEyMCkiLz48cGF0aCBmaWxsPSJub25lIiBkPSJNLTQyMi4wNjYtNDcuMzM1YTM2MC4zIDM2MC4zIDAgMCAxIDAgMzYwLjI5N00tNDY2Ljg3NS0zLjM3NWEyOTkuOTggMjk5Ljk4IDAgMCAxIDAgMjcyLjM3N00tNTE0Ljc1OCAzNS4xM2EyNDAuMTcgMjQwLjE3IDAgMCAxIDAgMTk1LjM2OCIgc3R5bGU9ImZpbGw6IzAwMDtmaWxsLW9wYWNpdHk6MDtmaWxsLXJ1bGU6ZXZlbm9kZDtzdHJva2U6I2ZmZjtzdHJva2Utd2lkdGg6MzU7c3Ryb2tlLWxpbmVjYXA6cm91bmQ7c3Ryb2tlLWxpbmVqb2luOm1pdGVyO3N0cm9rZS1taXRlcmxpbWl0OjQ7c3Ryb2tlLWRhc2hhcnJheTpub25lO3N0cm9rZS1vcGFjaXR5OjEiIHRyYW5zZm9ybT0icm90YXRlKC0xMjApIi8+PHBhdGggZD0ibTU5MS42MDUgNDA3LjA4MS0xMTQuMzU5IDk4LjkxMkgzNjkuMDEyVjYzMy4yOGgxMDYuNTkzbDExNiAxMDAuMzR6IiBzdHlsZT0iZmlsbDojYzhjOGM4O2ZpbGwtb3BhY2l0eToxO2ZpbGwtcnVsZTpldmVub2RkO3N0cm9rZTojZmZmO3N0cm9rZS13aWR0aDozMy4zMzM7c3Ryb2tlLWxpbmVjYXA6cm91bmQ7c3Ryb2tlLWxpbmVqb2luOnJvdW5kO3N0cm9rZS1taXRlcmxpbWl0OjQ7c3Ryb2tlLWRhc2hhcnJheTpub25lO3N0cm9rZS1vcGFjaXR5OjEiLz48cGF0aCBmaWxsPSJub25lIiBkPSJNNzkyLjMzNSAzOTIuMjMyYTM2MC4zIDM2MC4zIDAgMCAxIDAgMzYwLjI5N003NDcuNTk0IDQzNi4xOTJhMjk5Ljk4IDI5OS45OCAwIDAgMSAwIDI3Mi4zNzdNNjk5LjcxIDQ3NC42OTZhMjQwLjE3IDI0MC4xNyAwIDAgMSAwIDE5NS4zNjgiIHN0eWxlPSJmaWxsOiMwMDA7ZmlsbC1vcGFjaXR5OjA7ZmlsbC1ydWxlOmV2ZW5vZGQ7c3Ryb2tlOiNmZmY7c3Ryb2tlLXdpZHRoOjM1O3N0cm9rZS1saW5lY2FwOnJvdW5kO3N0cm9rZS1saW5lam9pbjptaXRlcjtzdHJva2UtbWl0ZXJsaW1pdDo0O3N0cm9rZS1kYXNoYXJyYXk6bm9uZTtzdHJva2Utb3BhY2l0eToxIi8+PHBhdGggZmlsbD0ibm9uZSIgZD0iTTU2NS43NDMtODc5LjI1NGEzNjAuMyAzNjAuMyAwIDAgMSAwIDM2MC4yOTdNNTIxLjAwMi04MzUuMjk1YTI5OS45OCAyOTkuOTggMCAwIDEgMCAyNzIuMzc4TTQ3My4xMTgtNzk2Ljc5YTI0MC4xNyAyNDAuMTcgMCAwIDEgMCAxOTUuMzY4IiBzdHlsZT0iZmlsbDojMDAwO2ZpbGwtb3BhY2l0eTowO2ZpbGwtcnVsZTpldmVub2RkO3N0cm9rZTojZmZmO3N0cm9rZS13aWR0aDozNTtzdHJva2UtbGluZWNhcDpyb3VuZDtzdHJva2UtbGluZWpvaW46bWl0ZXI7c3Ryb2tlLW1pdGVybGltaXQ6NDtzdHJva2UtZGFzaGFycmF5Om5vbmU7c3Ryb2tlLW9wYWNpdHk6MSIgdHJhbnNmb3JtPSJyb3RhdGUoMTIwKSIvPjwvZz48L3N2Zz4=",
2025-02-18 13-34-30.523 [Debug] (Server)          "extension": "svg"
2025-02-18 13-34-30.523 [Debug] (Server)       },
2025-02-18 13-34-30.523 [Debug] (Server)       "artUrl": "http://192.168.1.10:1780/__image_cache?name=e0f65f56fe83483156c8eac243304974.svg",
2025-02-18 13-34-30.523 [Debug] (Server)       "artist": [
2025-02-18 13-34-30.523 [Debug] (Server)          "artist"
2025-02-18 13-34-30.523 [Debug] (Server)       ],
2025-02-18 13-34-30.523 [Debug] (Server)       "title": "track 1"
2025-02-18 13-34-30.523 [Debug] (Server)    },
2025-02-18 13-34-30.523 [Debug] (Server)    "mute": false,
2025-02-18 13-34-30.523 [Debug] (Server)    "playbackStatus": "playing",
2025-02-18 13-34-30.523 [Debug] (Server)    "position": 0.0,
2025-02-18 13-34-30.523 [Debug] (Server)    "rate": 1.0,
2025-02-18 13-34-30.523 [Debug] (Server)    "shuffle": false,
2025-02-18 13-34-30.523 [Debug] (Server)    "volume": 100
2025-02-18 13-34-30.523 [Debug] (Server) }
2025-02-18 13-34-30.562 [Info] (AsioStream) No data since 120 ms, switching to idle
2025-02-18 13-34-30.786 [Notice] (StreamServer) StreamServer::NewConnection: ::ffff:192.168.1.25
2025-02-18 13-34-30.794 [Debug] (StreamSessionTCP) getNextMessage: Hello, size: 227, id: 7016, refers: 0
2025-02-18 13-34-30.795 [Debug] (Server) onMessageReceived: Hello, size: 227, id: 7016, refers: 0, sent: 9082,812548, recv: 2026860,226969
2025-02-18 13-34-30.795 [Info] (Server) Hello from d8:bb:c1:6c:5e:9b, host: DESKTOP-T1OT844, v0.31.100, ClientName: Snapclient, OS: Fedora Linux 41 (KDE Plasma), Arch: x86_64, Protocol version: 2
2025-02-18 13-34-30.795 [Debug] (Server) Sending ServerSettings to d8:bb:c1:6c:5e:9b
2025-02-18 13-34-30.795 [Debug] (Server) Group: 4752aebd-eb0b-239f-7b88-2a062a39dda2, stream: mpd
2025-02-18 13-34-30.795 [Debug] (Server) Sending codec header to d8:bb:c1:6c:5e:9b
2025-02-18 13-34-30.795 [Trace] (StreamSession) outstanding async_write
2025-02-18 13-34-31.324 [Notice] (StreamServer) StreamServer::NewConnection: ::ffff:192.168.1.61
2025-02-18 13-34-31.343 [Debug] (StreamSessionTCP) getNextMessage: Hello, size: 202, id: 3942, refers: 0
2025-02-18 13-34-31.343 [Debug] (Server) onMessageReceived: Hello, size: 202, id: 3942, refers: 0, sent: 1125527,754204, recv: 2026860,775491
2025-02-18 13-34-31.343 [Info] (Server) Hello from 1c:75:08:0d:e3:a7, host: hifi, v0.29.0, ClientName: Snapclient, OS: TinyCoreLinux 15.0, Arch: i686, Protocol version: 2
2025-02-18 13-34-31.343 [Debug] (Server) Sending ServerSettings to 1c:75:08:0d:e3:a7
2025-02-18 13-34-31.343 [Debug] (Server) Group: be73a7c5-6dee-8a3f-766d-db9cac7cdaa6, stream: mpd
2025-02-18 13-34-31.343 [Debug] (Server) Sending codec header to 1c:75:08:0d:e3:a7
2025-02-18 13-34-31.343 [Trace] (StreamSession) outstanding async_write
2025-02-18 13-34-31.348 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 3943, refers: 0
2025-02-18 13-34-31.348 [Debug] (Server) onMessageReceived: Time, size: 8, id: 3943, refers: 0, sent: 1125527,754964, recv: 2026860,780290
2025-02-18 13-34-31.435 [Info] (Avahi) Service 'Snapcast' successfully established.
2025-02-18 13-34-32.881 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 7069, refers: 0
2025-02-18 13-34-32.881 [Debug] (Server) onMessageReceived: Time, size: 8, id: 7069, refers: 0, sent: 9084,899506, recv: 2026862,313846
2025-02-18 13-34-33.343 [Debug] (Server) Saving config
2025-02-18 13-34-46.974 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4008, refers: 0
2025-02-18 13-34-46.974 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4008, refers: 0, sent: 1125543,385177, recv: 2026876,406539
2025-02-18 13-34-47.002 [Notice] (ControlServer) New connection from: ::ffff:192.168.1.25, port: 1780
2025-02-18 13-34-47.002 [Debug] (ControlSessionHTTP) ControlSessionHttp, mode: tcp, Local IP: ::ffff:192.168.1.10
2025-02-18 13-34-47.002 [Debug] (ControlSessionHTTP) start
2025-02-18 13-34-47.003 [Debug] (ControlSessionHTTP) read: 569, method: GET, content type: , target: /, body: 
2025-02-18 13-34-47.003 [Debug] (ControlSessionHTTP) path: /usr/share/snapserver/snapweb/index.html
2025-02-18 13-34-47.034 [Debug] (ControlSessionHTTP) read: 521, method: GET, content type: , target: /assets/index-BYMjFABP.js, body: 
2025-02-18 13-34-47.034 [Debug] (ControlSessionHTTP) path: /usr/share/snapserver/snapweb/assets/index-BYMjFABP.js
2025-02-18 13-34-47.035 [Notice] (ControlServer) New connection from: ::ffff:192.168.1.25, port: 1780
2025-02-18 13-34-47.035 [Debug] (ControlSessionHTTP) ControlSessionHttp, mode: tcp, Local IP: ::ffff:192.168.1.10
2025-02-18 13-34-47.035 [Debug] (ControlSessionHTTP) start
2025-02-18 13-34-47.035 [Notice] (ControlServer) New connection from: ::ffff:192.168.1.25, port: 1780
2025-02-18 13-34-47.035 [Debug] (ControlSessionHTTP) ControlSessionHttp, mode: tcp, Local IP: ::ffff:192.168.1.10
2025-02-18 13-34-47.035 [Debug] (ControlSessionHTTP) start
2025-02-18 13-34-47.035 [Debug] (ControlSessionHTTP) read: 552, method: GET, content type: , target: /assets/index-BDBx6C_I.css, body: 
2025-02-18 13-34-47.035 [Debug] (ControlSessionHTTP) path: /usr/share/snapserver/snapweb/assets/index-BDBx6C_I.css
2025-02-18 13-34-47.036 [Debug] (ControlSessionHTTP) read: 525, method: GET, content type: , target: /registerSW.js, body: 
2025-02-18 13-34-47.036 [Debug] (ControlSessionHTTP) path: /usr/share/snapserver/snapweb/registerSW.js
2025-02-18 13-34-47.206 [Debug] (ControlSessionHTTP) read: 606, method: GET, content type: , target: /apple-touch-icon-180x180.png, body: 
2025-02-18 13-34-47.206 [Debug] (ControlSessionHTTP) path: /usr/share/snapserver/snapweb/apple-touch-icon-180x180.png
2025-02-18 13-34-47.207 [Debug] (ControlSessionHTTP) read: 586, method: GET, content type: , target: /logo.svg, body: 
2025-02-18 13-34-47.207 [Debug] (ControlSessionHTTP) path: /usr/share/snapserver/snapweb/logo.svg
2025-02-18 13-34-47.207 [Error] (ControlSessionHTTP) Failed to shudown socket: system:107
2025-02-18 13-34-47.207 [Debug] (ControlSessionHTTP) ControlSessionHttp::~ControlSessionHttp()
2025-02-18 13-34-47.208 [Debug] (ControlSessionHTTP) ControlSessionHttp::~ControlSessionHttp()
2025-02-18 13-34-52.994 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4014, refers: 0
2025-02-18 13-34-52.994 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4014, refers: 0, sent: 1125549,404712, recv: 2026882,426013
2025-02-18 13-34-53.530 [Notice] (ControlServer) New connection from: ::ffff:192.168.1.25, port: 1780
2025-02-18 13-34-53.530 [Debug] (ControlSessionHTTP) ControlSessionHttp, mode: tcp, Local IP: ::ffff:192.168.1.10
2025-02-18 13-34-53.531 [Debug] (ControlSessionHTTP) start
2025-02-18 13-34-53.531 [Info] (ControlServer) Removing 2 inactive session(s), active sessions: 2
2025-02-18 13-34-53.531 [Debug] (ControlSessionHTTP) read: 692, method: GET, content type: , target: /jsonrpc, body: 
2025-02-18 13-34-53.531 [Debug] (ControlSessionHTTP) websocket upgrade, target: /jsonrpc
2025-02-18 13-34-53.531 [Debug] (ControlSessionWS) ControlSessionWebsocket, mode: tcp
2025-02-18 13-34-53.531 [Debug] (ControlSessionHTTP) ControlSessionHttp::~ControlSessionHttp()
2025-02-18 13-34-53.532 [Notice] (ControlServer) New connection from: ::ffff:192.168.1.25, port: 1780
2025-02-18 13-34-53.532 [Debug] (ControlSessionHTTP) ControlSessionHttp, mode: tcp, Local IP: ::ffff:192.168.1.10
2025-02-18 13-34-53.532 [Debug] (ControlSessionHTTP) start
2025-02-18 13-34-53.532 [Info] (ControlServer) Removing 1 inactive session(s), active sessions: 3
2025-02-18 13-34-53.532 [Debug] (ControlSessionHTTP) read: 481, method: GET, content type: , target: /jsonrpc, body: 
2025-02-18 13-34-53.532 [Debug] (ControlSessionHTTP) websocket upgrade, target: /jsonrpc
2025-02-18 13-34-53.532 [Debug] (ControlSessionWS) ControlSessionWebsocket, mode: tcp
2025-02-18 13-34-53.532 [Debug] (ControlSessionHTTP) ControlSessionHttp::~ControlSessionHttp()
2025-02-18 13-34-53.563 [Trace] (ControlSessionWS) Wrote 4652 bytes to web socket
2025-02-18 13-34-53.603 [Debug] (ControlSessionHTTP) read: 636, method: GET, content type: , target: /__image_cache?name=e0f65f56fe83483156c8eac243304974.svg, body: 
2025-02-18 13-34-53.603 [Debug] (ControlSessionHTTP) image cache: e0f65f56fe83483156c8eac243304974.svg, found: 1
2025-02-18 13-34-56.002 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4017, refers: 0
2025-02-18 13-34-56.002 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4017, refers: 0, sent: 1125552,413323, recv: 2026885,434721
2025-02-18 13-34-56.167 [Debug] (Server) Saving config
2025-02-18 13-34-58.008 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4019, refers: 0
2025-02-18 13-34-58.008 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4019, refers: 0, sent: 1125554,419389, recv: 2026887,440639
2025-02-18 13-34-58.067 [Info] (PcmStream) State changed: mpd, state: idle => playing
2025-02-18 13-34-58.067 [Info] (Server) onStateChanged (mpd): playing
2025-02-18 13-34-58.067 [Info] (ControlServer) Removing 1 inactive session(s), active sessions: 3
2025-02-18 13-34-58.067 [Trace] (ControlSessionWS) Wrote 3021 bytes to web socket
2025-02-18 13-34-58.067 [Trace] (ControlSessionWS) Wrote 3021 bytes to web socket
2025-02-18 13-34-58.972 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 7095, refers: 0
2025-02-18 13-34-58.973 [Debug] (Server) onMessageReceived: Time, size: 8, id: 7095, refers: 0, sent: 9110,990788, recv: 2026888,404964
2025-02-18 13-34-59.011 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4020, refers: 0
2025-02-18 13-34-59.011 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4020, refers: 0, sent: 1125555,422112, recv: 2026888,443390
2025-02-18 13-34-59.601 [Debug] (Server) Saving config
2025-02-18 13-34-59.710 [Info] (Server) onResync (mpd): 63.1264 ms
2025-02-18 13-34-59.974 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 7096, refers: 0
2025-02-18 13-34-59.974 [Debug] (Server) onMessageReceived: Time, size: 8, id: 7096, refers: 0, sent: 9111,992274, recv: 2026889,406525
2025-02-18 13-35-00.014 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4021, refers: 0
2025-02-18 13-35-00.014 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4021, refers: 0, sent: 1125556,425088, recv: 2026889,446334
2025-02-18 13-35-00.976 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 7097, refers: 0
2025-02-18 13-35-00.976 [Debug] (Server) onMessageReceived: Time, size: 8, id: 7097, refers: 0, sent: 9112,994192, recv: 2026890,408392
2025-02-18 13-35-01.017 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4022, refers: 0
2025-02-18 13-35-01.017 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4022, refers: 0, sent: 1125557,428016, recv: 2026890,449299
2025-02-18 13-35-01.104 [Debug] (ControlSessionWS) ControlSessionWebsocket::~ControlSessionWebsocket()
2025-02-18 13-35-01.977 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 7098, refers: 0
2025-02-18 13-35-01.977 [Debug] (Server) onMessageReceived: Time, size: 8, id: 7098, refers: 0, sent: 9113,995722, recv: 2026891,409828
2025-02-18 13-35-02.020 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4023, refers: 0
2025-02-18 13-35-02.020 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4023, refers: 0, sent: 1125558,430676, recv: 2026891,452603
2025-02-18 13-35-02.471 [Info] (ControlRequest) Stream.Control id: mpd, command: "next", params: ""
2025-02-18 13-35-02.471 [Debug] (PcmStream) next
2025-02-18 13-35-02.471 [Info] (Script) Sending request: {"id":1,"jsonrpc":"2.0","method":"Plugin.Stream.Player.Control","params":{"command":"next"}}
2025-02-18 13-35-02.472 [Debug] (PcmStream) Notification method: Plugin.Stream.Player.Properties, params: {"canControl":true,"canGoNext":true,"canGoPrevious":true,"canPause":true,"canPlay":true,"canSeek":false,"loopStatus":"none","metadata":{"artData":{"data":"PD94bWwgdmVyc2lvbj0iMS4wIiBlbmNvZGluZz0iVVRGLTgiIHN0YW5kYWxvbmU9Im5vIj8+CjxzdmcgeG1sbnM9Imh0dHA6Ly93d3cudzMub3JnLzIwMDAvc3ZnIiBoZWlnaHQ9IjE2OHB4IiB3aWR0aD0iMTY4cHgiIHZlcnNpb249IjEuMSIgdmlld0JveD0iMCAwIDE2OCAxNjgiPgogPHBhdGggZmlsbD0iIzFFRDc2MCIgZD0ibTgzLjk5NiAwLjI3N2MtNDYuMjQ5IDAtODMuNzQzIDM3LjQ5My04My43NDMgODMuNzQyIDAgNDYuMjUxIDM3LjQ5NCA4My43NDEgODMuNzQzIDgzLjc0MSA0Ni4yNTQgMCA4My43NDQtMzcuNDkgODMuNzQ0LTgzLjc0MSAwLTQ2LjI0Ni0zNy40OS04My43MzgtODMuNzQ1LTgzLjczOGwwLjAwMS0wLjAwNHptMzguNDA0IDEyMC43OGMtMS41IDIuNDYtNC43MiAzLjI0LTcuMTggMS43My0xOS42NjItMTIuMDEtNDQuNDE0LTE0LjczLTczLjU2NC04LjA3LTIuODA5IDAuNjQtNS42MDktMS4xMi02LjI0OS0zLjkzLTAuNjQzLTIuODEgMS4xMS01LjYxIDMuOTI2LTYuMjUgMzEuOS03LjI5MSA1OS4yNjMtNC4xNSA4MS4zMzcgOS4zNCAyLjQ2IDEuNTEgMy4yNCA0LjcyIDEuNzMgNy4xOHptMTAuMjUtMjIuODA1Yy0xLjg5IDMuMDc1LTUuOTEgNC4wNDUtOC45OCAyLjE1NS0yMi41MS0xMy44MzktNTYuODIzLTE3Ljg0Ni04My40NDgtOS43NjQtMy40NTMgMS4wNDMtNy4xLTAuOTAzLTguMTQ4LTQuMzUtMS4wNC0zLjQ1MyAwLjkwNy03LjA5MyA0LjM1NC04LjE0MyAzMC40MTMtOS4yMjggNjguMjIyLTQuNzU4IDk0LjA3MiAxMS4xMjcgMy4wNyAxLjg5IDQuMDQgNS45MSAyLjE1IDguOTc2di0wLjAwMXptMC44OC0yMy43NDRjLTI2Ljk5LTE2LjAzMS03MS41Mi0xNy41MDUtOTcuMjg5LTkuNjg0LTQuMTM4IDEuMjU1LTguNTE0LTEuMDgxLTkuNzY4LTUuMjE5LTEuMjU0LTQuMTQgMS4wOC04LjUxMyA1LjIyMS05Ljc3MSAyOS41ODEtOC45OCA3OC43NTYtNy4yNDUgMTA5LjgzIDExLjIwMiAzLjczIDIuMjA5IDQuOTUgNy4wMTYgMi43NCAxMC43MzMtMi4yIDMuNzIyLTcuMDIgNC45NDktMTAuNzMgMi43Mzl6Ii8+Cjwvc3ZnPgo=","extension":"svg"},"artist":["artist"],"title":"track 2"},"mute":false,"playbackStatus":"playing","position":0,"rate":1.0,"shuffle":false,"volume":100}
2025-02-18 13-35-02.473 [Debug] (PcmStream) Received properties notification
2025-02-18 13-35-02.473 [Debug] (PcmStream) setProperties, stream: mpd, properties: {"canControl":true,"canGoNext":true,"canGoPrevious":true,"canPause":true,"canPlay":true,"canSeek":false,"loopStatus":"none","metadata":{"artData":{"data":"PD94bWwgdmVyc2lvbj0iMS4wIiBlbmNvZGluZz0iVVRGLTgiIHN0YW5kYWxvbmU9Im5vIj8+CjxzdmcgeG1sbnM9Imh0dHA6Ly93d3cudzMub3JnLzIwMDAvc3ZnIiBoZWlnaHQ9IjE2OHB4IiB3aWR0aD0iMTY4cHgiIHZlcnNpb249IjEuMSIgdmlld0JveD0iMCAwIDE2OCAxNjgiPgogPHBhdGggZmlsbD0iIzFFRDc2MCIgZD0ibTgzLjk5NiAwLjI3N2MtNDYuMjQ5IDAtODMuNzQzIDM3LjQ5My04My43NDMgODMuNzQyIDAgNDYuMjUxIDM3LjQ5NCA4My43NDEgODMuNzQzIDgzLjc0MSA0Ni4yNTQgMCA4My43NDQtMzcuNDkgODMuNzQ0LTgzLjc0MSAwLTQ2LjI0Ni0zNy40OS04My43MzgtODMuNzQ1LTgzLjczOGwwLjAwMS0wLjAwNHptMzguNDA0IDEyMC43OGMtMS41IDIuNDYtNC43MiAzLjI0LTcuMTggMS43My0xOS42NjItMTIuMDEtNDQuNDE0LTE0LjczLTczLjU2NC04LjA3LTIuODA5IDAuNjQtNS42MDktMS4xMi02LjI0OS0zLjkzLTAuNjQzLTIuODEgMS4xMS01LjYxIDMuOTI2LTYuMjUgMzEuOS03LjI5MSA1OS4yNjMtNC4xNSA4MS4zMzcgOS4zNCAyLjQ2IDEuNTEgMy4yNCA0LjcyIDEuNzMgNy4xOHptMTAuMjUtMjIuODA1Yy0xLjg5IDMuMDc1LTUuOTEgNC4wNDUtOC45OCAyLjE1NS0yMi41MS0xMy44MzktNTYuODIzLTE3Ljg0Ni04My40NDgtOS43NjQtMy40NTMgMS4wNDMtNy4xLTAuOTAzLTguMTQ4LTQuMzUtMS4wNC0zLjQ1MyAwLjkwNy03LjA5MyA0LjM1NC04LjE0MyAzMC40MTMtOS4yMjggNjguMjIyLTQuNzU4IDk0LjA3MiAxMS4xMjcgMy4wNyAxLjg5IDQuMDQgNS45MSAyLjE1IDguOTc2di0wLjAwMXptMC44OC0yMy43NDRjLTI2Ljk5LTE2LjAzMS03MS41Mi0xNy41MDUtOTcuMjg5LTkuNjg0LTQuMTM4IDEuMjU1LTguNTE0LTEuMDgxLTkuNzY4LTUuMjE5LTEuMjU0LTQuMTQgMS4wOC04LjUxMyA1LjIyMS05Ljc3MSAyOS41ODEtOC45OCA3OC43NTYtNy4yNDUgMTA5LjgzIDExLjIwMiAzLjczIDIuMjA5IDQuOTUgNy4wMTYgMi43NCAxMC43MzMtMi4yIDMuNzIyLTcuMDIgNC45NDktMTAuNzMgMi43Mzl6Ii8+Cjwvc3ZnPgo=","extension":"svg"},"artUrl":"http://192.168.1.10:1780/__image_cache?name=5224c6da8763640d94575d7e246f1c52.svg","artist":["artist"],"title":"track 2"},"mute":false,"playbackStatus":"playing","position":0.0,"rate":1.0,"shuffle":false,"volume":100}
2025-02-18 13-35-02.473 [Debug] (Server) Properties changed, stream: mpd, properties: {
2025-02-18 13-35-02.473 [Debug] (Server)    "canControl": true,
2025-02-18 13-35-02.473 [Debug] (Server)    "canGoNext": true,
2025-02-18 13-35-02.473 [Debug] (Server)    "canGoPrevious": true,
2025-02-18 13-35-02.473 [Debug] (Server)    "canPause": true,
2025-02-18 13-35-02.473 [Debug] (Server)    "canPlay": true,
2025-02-18 13-35-02.473 [Debug] (Server)    "canSeek": false,
2025-02-18 13-35-02.473 [Debug] (Server)    "loopStatus": "none",
2025-02-18 13-35-02.473 [Debug] (Server)    "metadata": {
2025-02-18 13-35-02.473 [Debug] (Server)       "artData": {
2025-02-18 13-35-02.473 [Debug] (Server)          "data": "PD94bWwgdmVyc2lvbj0iMS4wIiBlbmNvZGluZz0iVVRGLTgiIHN0YW5kYWxvbmU9Im5vIj8+CjxzdmcgeG1sbnM9Imh0dHA6Ly93d3cudzMub3JnLzIwMDAvc3ZnIiBoZWlnaHQ9IjE2OHB4IiB3aWR0aD0iMTY4cHgiIHZlcnNpb249IjEuMSIgdmlld0JveD0iMCAwIDE2OCAxNjgiPgogPHBhdGggZmlsbD0iIzFFRDc2MCIgZD0ibTgzLjk5NiAwLjI3N2MtNDYuMjQ5IDAtODMuNzQzIDM3LjQ5My04My43NDMgODMuNzQyIDAgNDYuMjUxIDM3LjQ5NCA4My43NDEgODMuNzQzIDgzLjc0MSA0Ni4yNTQgMCA4My43NDQtMzcuNDkgODMuNzQ0LTgzLjc0MSAwLTQ2LjI0Ni0zNy40OS04My43MzgtODMuNzQ1LTgzLjczOGwwLjAwMS0wLjAwNHptMzguNDA0IDEyMC43OGMtMS41IDIuNDYtNC43MiAzLjI0LTcuMTggMS43My0xOS42NjItMTIuMDEtNDQuNDE0LTE0LjczLTczLjU2NC04LjA3LTIuODA5IDAuNjQtNS42MDktMS4xMi02LjI0OS0zLjkzLTAuNjQzLTIuODEgMS4xMS01LjYxIDMuOTI2LTYuMjUgMzEuOS03LjI5MSA1OS4yNjMtNC4xNSA4MS4zMzcgOS4zNCAyLjQ2IDEuNTEgMy4yNCA0LjcyIDEuNzMgNy4xOHptMTAuMjUtMjIuODA1Yy0xLjg5IDMuMDc1LTUuOTEgNC4wNDUtOC45OCAyLjE1NS0yMi41MS0xMy44MzktNTYuODIzLTE3Ljg0Ni04My40NDgtOS43NjQtMy40NTMgMS4wNDMtNy4xLTAuOTAzLTguMTQ4LTQuMzUtMS4wNC0zLjQ1MyAwLjkwNy03LjA5MyA0LjM1NC04LjE0MyAzMC40MTMtOS4yMjggNjguMjIyLTQuNzU4IDk0LjA3MiAxMS4xMjcgMy4wNyAxLjg5IDQuMDQgNS45MSAyLjE1IDguOTc2di0wLjAwMXptMC44OC0yMy43NDRjLTI2Ljk5LTE2LjAzMS03MS41Mi0xNy41MDUtOTcuMjg5LTkuNjg0LTQuMTM4IDEuMjU1LTguNTE0LTEuMDgxLTkuNzY4LTUuMjE5LTEuMjU0LTQuMTQgMS4wOC04LjUxMyA1LjIyMS05Ljc3MSAyOS41ODEtOC45OCA3OC43NTYtNy4yNDUgMTA5LjgzIDExLjIwMiAzLjczIDIuMjA5IDQuOTUgNy4wMTYgMi43NCAxMC43MzMtMi4yIDMuNzIyLTcuMDIgNC45NDktMTAuNzMgMi43Mzl6Ii8+Cjwvc3ZnPgo=",
2025-02-18 13-35-02.473 [Debug] (Server)          "extension": "svg"
2025-02-18 13-35-02.473 [Debug] (Server)       },
2025-02-18 13-35-02.473 [Debug] (Server)       "artUrl": "http://192.168.1.10:1780/__image_cache?name=5224c6da8763640d94575d7e246f1c52.svg",
2025-02-18 13-35-02.473 [Debug] (Server)       "artist": [
2025-02-18 13-35-02.473 [Debug] (Server)          "artist"
2025-02-18 13-35-02.473 [Debug] (Server)       ],
2025-02-18 13-35-02.473 [Debug] (Server)       "title": "track 2"
2025-02-18 13-35-02.473 [Debug] (Server)    },
2025-02-18 13-35-02.473 [Debug] (Server)    "mute": false,
2025-02-18 13-35-02.473 [Debug] (Server)    "playbackStatus": "playing",
2025-02-18 13-35-02.473 [Debug] (Server)    "position": 0.0,
2025-02-18 13-35-02.473 [Debug] (Server)    "rate": 1.0,
2025-02-18 13-35-02.473 [Debug] (Server)    "shuffle": false,
2025-02-18 13-35-02.473 [Debug] (Server)    "volume": 100
2025-02-18 13-35-02.473 [Debug] (Server) }
2025-02-18 13-35-02.474 [Info] (ControlServer) Removing 1 inactive session(s), active sessions: 2
2025-02-18 13-35-02.474 [Info] (Script) Wrote 1882 bytes to web socket
2025-02-18 13-35-02.474 [Info] (Script) Response: {"id":1,"jsonrpc":"2.0","result":"ok"}, id: 1
2025-02-18 13-35-02.475 [Debug] (ControlRequest) Response to 'next': control:0, message: Success, msg: Success, category: control
2025-02-18 13-35-02.475 [Trace] (ControlSessionWS) Wrote 38 bytes to web socket
2025-02-18 13-35-02.504 [Debug] (ControlSessionHTTP) read: 633, method: GET, content type: , target: /__image_cache?name=5224c6da8763640d94575d7e246f1c52.svg, body: 
2025-02-18 13-35-02.504 [Debug] (ControlSessionHTTP) image cache: 5224c6da8763640d94575d7e246f1c52.svg, found: 1
2025-02-18 13-35-02.979 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 7099, refers: 0
2025-02-18 13-35-02.979 [Debug] (Server) onMessageReceived: Time, size: 8, id: 7099, refers: 0, sent: 9114,997143, recv: 2026892,411343
2025-02-18 13-35-03.023 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4024, refers: 0
2025-02-18 13-35-03.023 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4024, refers: 0, sent: 1125559,433870, recv: 2026892,455224
2025-02-18 13-35-03.980 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 7100, refers: 0
2025-02-18 13-35-03.980 [Debug] (Server) onMessageReceived: Time, size: 8, id: 7100, refers: 0, sent: 9115,998595, recv: 2026893,412869
2025-02-18 13-35-04.025 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4025, refers: 0
2025-02-18 13-35-04.026 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4025, refers: 0, sent: 1125560,436582, recv: 2026893,457936
2025-02-18 13-35-04.475 [Debug] (Server) Saving config
2025-02-18 13-35-04.568 [Info] (Server) onResync (mpd): 57.3618 ms
2025-02-18 13-35-04.982 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 7101, refers: 0
2025-02-18 13-35-04.982 [Debug] (Server) onMessageReceived: Time, size: 8, id: 7101, refers: 0, sent: 9117,310, recv: 2026894,414466
2025-02-18 13-35-05.028 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4026, refers: 0
2025-02-18 13-35-05.028 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4026, refers: 0, sent: 1125561,439336, recv: 2026894,460611
2025-02-18 13-35-05.984 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 7102, refers: 0
2025-02-18 13-35-05.984 [Debug] (Server) onMessageReceived: Time, size: 8, id: 7102, refers: 0, sent: 9118,2275, recv: 2026895,416461
2025-02-18 13-35-06.031 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4027, refers: 0
2025-02-18 13-35-06.031 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4027, refers: 0, sent: 1125562,442435, recv: 2026895,463849
2025-02-18 13-35-06.827 [Info] (ControlRequest) Stream.Control id: mpd, command: "previous", params: ""
2025-02-18 13-35-06.827 [Debug] (PcmStream) previous
2025-02-18 13-35-06.828 [Info] (Script) Sending request: {"id":2,"jsonrpc":"2.0","method":"Plugin.Stream.Player.Control","params":{"command":"previous"}}
2025-02-18 13-35-06.828 [Debug] (PcmStream) Notification method: Plugin.Stream.Player.Properties, params: {"canControl":true,"canGoNext":true,"canGoPrevious":true,"canPause":true,"canPlay":true,"canSeek":false,"loopStatus":"none","metadata":{"artData":{"data":"PHN2ZyB4bWxucz0iaHR0cDovL3d3dy53My5vcmcvMjAwMC9zdmciIHdpZHRoPSIxNDMwIiBoZWlnaHQ9IjE0MzAiIHZpZXdCb3g9IjAgMCAxMzQwLjYyNSAxMzQwLjYyNSI+PGcgdHJhbnNmb3JtPSJtYXRyaXgoMS4wMzAyIDAgMCAxLjAzMDIgMTc1LjQ5NSA4Mi43MzIpIj48Y2lyY2xlIGN4PSItNzM0LjA5MyIgY3k9IjEzMC43ODQiIHI9IjQzMS4yNSIgc3R5bGU9ImZpbGw6I2ZmYzEwNztmaWxsLW9wYWNpdHk6MTtzdHJva2Utd2lkdGg6MTAuNDgxNiIgdHJhbnNmb3JtPSJyb3RhdGUoLTEyMCkiLz48cGF0aCBmaWxsPSJub25lIiBkPSJNLTQyMi4wNjYtNDcuMzM1YTM2MC4zIDM2MC4zIDAgMCAxIDAgMzYwLjI5N00tNDY2Ljg3NS0zLjM3NWEyOTkuOTggMjk5Ljk4IDAgMCAxIDAgMjcyLjM3N00tNTE0Ljc1OCAzNS4xM2EyNDAuMTcgMjQwLjE3IDAgMCAxIDAgMTk1LjM2OCIgc3R5bGU9ImZpbGw6IzAwMDtmaWxsLW9wYWNpdHk6MDtmaWxsLXJ1bGU6ZXZlbm9kZDtzdHJva2U6I2ZmZjtzdHJva2Utd2lkdGg6MzU7c3Ryb2tlLWxpbmVjYXA6cm91bmQ7c3Ryb2tlLWxpbmVqb2luOm1pdGVyO3N0cm9rZS1taXRlcmxpbWl0OjQ7c3Ryb2tlLWRhc2hhcnJheTpub25lO3N0cm9rZS1vcGFjaXR5OjEiIHRyYW5zZm9ybT0icm90YXRlKC0xMjApIi8+PHBhdGggZD0ibTU5MS42MDUgNDA3LjA4MS0xMTQuMzU5IDk4LjkxMkgzNjkuMDEyVjYzMy4yOGgxMDYuNTkzbDExNiAxMDAuMzR6IiBzdHlsZT0iZmlsbDojYzhjOGM4O2ZpbGwtb3BhY2l0eToxO2ZpbGwtcnVsZTpldmVub2RkO3N0cm9rZTojZmZmO3N0cm9rZS13aWR0aDozMy4zMzM7c3Ryb2tlLWxpbmVjYXA6cm91bmQ7c3Ryb2tlLWxpbmVqb2luOnJvdW5kO3N0cm9rZS1taXRlcmxpbWl0OjQ7c3Ryb2tlLWRhc2hhcnJheTpub25lO3N0cm9rZS1vcGFjaXR5OjEiLz48cGF0aCBmaWxsPSJub25lIiBkPSJNNzkyLjMzNSAzOTIuMjMyYTM2MC4zIDM2MC4zIDAgMCAxIDAgMzYwLjI5N003NDcuNTk0IDQzNi4xOTJhMjk5Ljk4IDI5OS45OCAwIDAgMSAwIDI3Mi4zNzdNNjk5LjcxIDQ3NC42OTZhMjQwLjE3IDI0MC4xNyAwIDAgMSAwIDE5NS4zNjgiIHN0eWxlPSJmaWxsOiMwMDA7ZmlsbC1vcGFjaXR5OjA7ZmlsbC1ydWxlOmV2ZW5vZGQ7c3Ryb2tlOiNmZmY7c3Ryb2tlLXdpZHRoOjM1O3N0cm9rZS1saW5lY2FwOnJvdW5kO3N0cm9rZS1saW5lam9pbjptaXRlcjtzdHJva2UtbWl0ZXJsaW1pdDo0O3N0cm9rZS1kYXNoYXJyYXk6bm9uZTtzdHJva2Utb3BhY2l0eToxIi8+PHBhdGggZmlsbD0ibm9uZSIgZD0iTTU2NS43NDMtODc5LjI1NGEzNjAuMyAzNjAuMyAwIDAgMSAwIDM2MC4yOTdNNTIxLjAwMi04MzUuMjk1YTI5OS45OCAyOTkuOTggMCAwIDEgMCAyNzIuMzc4TTQ3My4xMTgtNzk2Ljc5YTI0MC4xNyAyNDAuMTcgMCAwIDEgMCAxOTUuMzY4IiBzdHlsZT0iZmlsbDojMDAwO2ZpbGwtb3BhY2l0eTowO2ZpbGwtcnVsZTpldmVub2RkO3N0cm9rZTojZmZmO3N0cm9rZS13aWR0aDozNTtzdHJva2UtbGluZWNhcDpyb3VuZDtzdHJva2UtbGluZWpvaW46bWl0ZXI7c3Ryb2tlLW1pdGVybGltaXQ6NDtzdHJva2UtZGFzaGFycmF5Om5vbmU7c3Ryb2tlLW9wYWNpdHk6MSIgdHJhbnNmb3JtPSJyb3RhdGUoMTIwKSIvPjwvZz48L3N2Zz4=","extension":"svg"},"artist":["artist"],"title":"track 1"},"mute":false,"playbackStatus":"playing","position":0,"rate":1.0,"shuffle":false,"volume":100}
2025-02-18 13-35-06.829 [Debug] (PcmStream) Received properties notification
2025-02-18 13-35-06.829 [Debug] (PcmStream) setProperties, stream: mpd, properties: {"canControl":true,"canGoNext":true,"canGoPrevious":true,"canPause":true,"canPlay":true,"canSeek":false,"loopStatus":"none","metadata":{"artData":{"data":"PHN2ZyB4bWxucz0iaHR0cDovL3d3dy53My5vcmcvMjAwMC9zdmciIHdpZHRoPSIxNDMwIiBoZWlnaHQ9IjE0MzAiIHZpZXdCb3g9IjAgMCAxMzQwLjYyNSAxMzQwLjYyNSI+PGcgdHJhbnNmb3JtPSJtYXRyaXgoMS4wMzAyIDAgMCAxLjAzMDIgMTc1LjQ5NSA4Mi43MzIpIj48Y2lyY2xlIGN4PSItNzM0LjA5MyIgY3k9IjEzMC43ODQiIHI9IjQzMS4yNSIgc3R5bGU9ImZpbGw6I2ZmYzEwNztmaWxsLW9wYWNpdHk6MTtzdHJva2Utd2lkdGg6MTAuNDgxNiIgdHJhbnNmb3JtPSJyb3RhdGUoLTEyMCkiLz48cGF0aCBmaWxsPSJub25lIiBkPSJNLTQyMi4wNjYtNDcuMzM1YTM2MC4zIDM2MC4zIDAgMCAxIDAgMzYwLjI5N00tNDY2Ljg3NS0zLjM3NWEyOTkuOTggMjk5Ljk4IDAgMCAxIDAgMjcyLjM3N00tNTE0Ljc1OCAzNS4xM2EyNDAuMTcgMjQwLjE3IDAgMCAxIDAgMTk1LjM2OCIgc3R5bGU9ImZpbGw6IzAwMDtmaWxsLW9wYWNpdHk6MDtmaWxsLXJ1bGU6ZXZlbm9kZDtzdHJva2U6I2ZmZjtzdHJva2Utd2lkdGg6MzU7c3Ryb2tlLWxpbmVjYXA6cm91bmQ7c3Ryb2tlLWxpbmVqb2luOm1pdGVyO3N0cm9rZS1taXRlcmxpbWl0OjQ7c3Ryb2tlLWRhc2hhcnJheTpub25lO3N0cm9rZS1vcGFjaXR5OjEiIHRyYW5zZm9ybT0icm90YXRlKC0xMjApIi8+PHBhdGggZD0ibTU5MS42MDUgNDA3LjA4MS0xMTQuMzU5IDk4LjkxMkgzNjkuMDEyVjYzMy4yOGgxMDYuNTkzbDExNiAxMDAuMzR6IiBzdHlsZT0iZmlsbDojYzhjOGM4O2ZpbGwtb3BhY2l0eToxO2ZpbGwtcnVsZTpldmVub2RkO3N0cm9rZTojZmZmO3N0cm9rZS13aWR0aDozMy4zMzM7c3Ryb2tlLWxpbmVjYXA6cm91bmQ7c3Ryb2tlLWxpbmVqb2luOnJvdW5kO3N0cm9rZS1taXRlcmxpbWl0OjQ7c3Ryb2tlLWRhc2hhcnJheTpub25lO3N0cm9rZS1vcGFjaXR5OjEiLz48cGF0aCBmaWxsPSJub25lIiBkPSJNNzkyLjMzNSAzOTIuMjMyYTM2MC4zIDM2MC4zIDAgMCAxIDAgMzYwLjI5N003NDcuNTk0IDQzNi4xOTJhMjk5Ljk4IDI5OS45OCAwIDAgMSAwIDI3Mi4zNzdNNjk5LjcxIDQ3NC42OTZhMjQwLjE3IDI0MC4xNyAwIDAgMSAwIDE5NS4zNjgiIHN0eWxlPSJmaWxsOiMwMDA7ZmlsbC1vcGFjaXR5OjA7ZmlsbC1ydWxlOmV2ZW5vZGQ7c3Ryb2tlOiNmZmY7c3Ryb2tlLXdpZHRoOjM1O3N0cm9rZS1saW5lY2FwOnJvdW5kO3N0cm9rZS1saW5lam9pbjptaXRlcjtzdHJva2UtbWl0ZXJsaW1pdDo0O3N0cm9rZS1kYXNoYXJyYXk6bm9uZTtzdHJva2Utb3BhY2l0eToxIi8+PHBhdGggZmlsbD0ibm9uZSIgZD0iTTU2NS43NDMtODc5LjI1NGEzNjAuMyAzNjAuMyAwIDAgMSAwIDM2MC4yOTdNNTIxLjAwMi04MzUuMjk1YTI5OS45OCAyOTkuOTggMCAwIDEgMCAyNzIuMzc4TTQ3My4xMTgtNzk2Ljc5YTI0MC4xNyAyNDAuMTcgMCAwIDEgMCAxOTUuMzY4IiBzdHlsZT0iZmlsbDojMDAwO2ZpbGwtb3BhY2l0eTowO2ZpbGwtcnVsZTpldmVub2RkO3N0cm9rZTojZmZmO3N0cm9rZS13aWR0aDozNTtzdHJva2UtbGluZWNhcDpyb3VuZDtzdHJva2UtbGluZWpvaW46bWl0ZXI7c3Ryb2tlLW1pdGVybGltaXQ6NDtzdHJva2UtZGFzaGFycmF5Om5vbmU7c3Ryb2tlLW9wYWNpdHk6MSIgdHJhbnNmb3JtPSJyb3RhdGUoMTIwKSIvPjwvZz48L3N2Zz4=","extension":"svg"},"artUrl":"http://192.168.1.10:1780/__image_cache?name=e0f65f56fe83483156c8eac243304974.svg","artist":["artist"],"title":"track 1"},"mute":false,"playbackStatus":"playing","position":0.0,"rate":1.0,"shuffle":false,"volume":100}
2025-02-18 13-35-06.829 [Debug] (Server) Properties changed, stream: mpd, properties: {
2025-02-18 13-35-06.829 [Debug] (Server)    "canControl": true,
2025-02-18 13-35-06.829 [Debug] (Server)    "canGoNext": true,
2025-02-18 13-35-06.829 [Debug] (Server)    "canGoPrevious": true,
2025-02-18 13-35-06.829 [Debug] (Server)    "canPause": true,
2025-02-18 13-35-06.829 [Debug] (Server)    "canPlay": true,
2025-02-18 13-35-06.829 [Debug] (Server)    "canSeek": false,
2025-02-18 13-35-06.829 [Debug] (Server)    "loopStatus": "none",
2025-02-18 13-35-06.829 [Debug] (Server)    "metadata": {
2025-02-18 13-35-06.829 [Debug] (Server)       "artData": {
2025-02-18 13-35-06.829 [Debug] (Server)          "data": "PHN2ZyB4bWxucz0iaHR0cDovL3d3dy53My5vcmcvMjAwMC9zdmciIHdpZHRoPSIxNDMwIiBoZWlnaHQ9IjE0MzAiIHZpZXdCb3g9IjAgMCAxMzQwLjYyNSAxMzQwLjYyNSI+PGcgdHJhbnNmb3JtPSJtYXRyaXgoMS4wMzAyIDAgMCAxLjAzMDIgMTc1LjQ5NSA4Mi43MzIpIj48Y2lyY2xlIGN4PSItNzM0LjA5MyIgY3k9IjEzMC43ODQiIHI9IjQzMS4yNSIgc3R5bGU9ImZpbGw6I2ZmYzEwNztmaWxsLW9wYWNpdHk6MTtzdHJva2Utd2lkdGg6MTAuNDgxNiIgdHJhbnNmb3JtPSJyb3RhdGUoLTEyMCkiLz48cGF0aCBmaWxsPSJub25lIiBkPSJNLTQyMi4wNjYtNDcuMzM1YTM2MC4zIDM2MC4zIDAgMCAxIDAgMzYwLjI5N00tNDY2Ljg3NS0zLjM3NWEyOTkuOTggMjk5Ljk4IDAgMCAxIDAgMjcyLjM3N00tNTE0Ljc1OCAzNS4xM2EyNDAuMTcgMjQwLjE3IDAgMCAxIDAgMTk1LjM2OCIgc3R5bGU9ImZpbGw6IzAwMDtmaWxsLW9wYWNpdHk6MDtmaWxsLXJ1bGU6ZXZlbm9kZDtzdHJva2U6I2ZmZjtzdHJva2Utd2lkdGg6MzU7c3Ryb2tlLWxpbmVjYXA6cm91bmQ7c3Ryb2tlLWxpbmVqb2luOm1pdGVyO3N0cm9rZS1taXRlcmxpbWl0OjQ7c3Ryb2tlLWRhc2hhcnJheTpub25lO3N0cm9rZS1vcGFjaXR5OjEiIHRyYW5zZm9ybT0icm90YXRlKC0xMjApIi8+PHBhdGggZD0ibTU5MS42MDUgNDA3LjA4MS0xMTQuMzU5IDk4LjkxMkgzNjkuMDEyVjYzMy4yOGgxMDYuNTkzbDExNiAxMDAuMzR6IiBzdHlsZT0iZmlsbDojYzhjOGM4O2ZpbGwtb3BhY2l0eToxO2ZpbGwtcnVsZTpldmVub2RkO3N0cm9rZTojZmZmO3N0cm9rZS13aWR0aDozMy4zMzM7c3Ryb2tlLWxpbmVjYXA6cm91bmQ7c3Ryb2tlLWxpbmVqb2luOnJvdW5kO3N0cm9rZS1taXRlcmxpbWl0OjQ7c3Ryb2tlLWRhc2hhcnJheTpub25lO3N0cm9rZS1vcGFjaXR5OjEiLz48cGF0aCBmaWxsPSJub25lIiBkPSJNNzkyLjMzNSAzOTIuMjMyYTM2MC4zIDM2MC4zIDAgMCAxIDAgMzYwLjI5N003NDcuNTk0IDQzNi4xOTJhMjk5Ljk4IDI5OS45OCAwIDAgMSAwIDI3Mi4zNzdNNjk5LjcxIDQ3NC42OTZhMjQwLjE3IDI0MC4xNyAwIDAgMSAwIDE5NS4zNjgiIHN0eWxlPSJmaWxsOiMwMDA7ZmlsbC1vcGFjaXR5OjA7ZmlsbC1ydWxlOmV2ZW5vZGQ7c3Ryb2tlOiNmZmY7c3Ryb2tlLXdpZHRoOjM1O3N0cm9rZS1saW5lY2FwOnJvdW5kO3N0cm9rZS1saW5lam9pbjptaXRlcjtzdHJva2UtbWl0ZXJsaW1pdDo0O3N0cm9rZS1kYXNoYXJyYXk6bm9uZTtzdHJva2Utb3BhY2l0eToxIi8+PHBhdGggZmlsbD0ibm9uZSIgZD0iTTU2NS43NDMtODc5LjI1NGEzNjAuMyAzNjAuMyAwIDAgMSAwIDM2MC4yOTdNNTIxLjAwMi04MzUuMjk1YTI5OS45OCAyOTkuOTggMCAwIDEgMCAyNzIuMzc4TTQ3My4xMTgtNzk2Ljc5YTI0MC4xNyAyNDAuMTcgMCAwIDEgMCAxOTUuMzY4IiBzdHlsZT0iZmlsbDojMDAwO2ZpbGwtb3BhY2l0eTowO2ZpbGwtcnVsZTpldmVub2RkO3N0cm9rZTojZmZmO3N0cm9rZS13aWR0aDozNTtzdHJva2UtbGluZWNhcDpyb3VuZDtzdHJva2UtbGluZWpvaW46bWl0ZXI7c3Ryb2tlLW1pdGVybGltaXQ6NDtzdHJva2UtZGFzaGFycmF5Om5vbmU7c3Ryb2tlLW9wYWNpdHk6MSIgdHJhbnNmb3JtPSJyb3RhdGUoMTIwKSIvPjwvZz48L3N2Zz4=",
2025-02-18 13-35-06.829 [Debug] (Server)          "extension": "svg"
2025-02-18 13-35-06.829 [Debug] (Server)       },
2025-02-18 13-35-06.829 [Debug] (Server)       "artUrl": "http://192.168.1.10:1780/__image_cache?name=e0f65f56fe83483156c8eac243304974.svg",
2025-02-18 13-35-06.829 [Debug] (Server)       "artist": [
2025-02-18 13-35-06.829 [Debug] (Server)          "artist"
2025-02-18 13-35-06.829 [Debug] (Server)       ],
2025-02-18 13-35-06.829 [Debug] (Server)       "title": "track 1"
2025-02-18 13-35-06.829 [Debug] (Server)    },
2025-02-18 13-35-06.829 [Debug] (Server)    "mute": false,
2025-02-18 13-35-06.829 [Debug] (Server)    "playbackStatus": "playing",
2025-02-18 13-35-06.829 [Debug] (Server)    "position": 0.0,
2025-02-18 13-35-06.829 [Debug] (Server)    "rate": 1.0,
2025-02-18 13-35-06.829 [Debug] (Server)    "shuffle": false,
2025-02-18 13-35-06.829 [Debug] (Server)    "volume": 100
2025-02-18 13-35-06.829 [Debug] (Server) }
2025-02-18 13-35-06.830 [Trace] (ControlSessionWS) Wrote 2658 bytes to web socket
2025-02-18 13-35-06.831 [Info] (Script) Response: {"id":2,"jsonrpc":"2.0","result":"ok"}, id: 2
2025-02-18 13-35-06.831 [Debug] (ControlRequest) Response to 'previous': control:0, message: Success, msg: Success, category: control
2025-02-18 13-35-06.831 [Trace] (ControlSessionWS) Wrote 38 bytes to web socket
2025-02-18 13-35-06.986 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 7103, refers: 0
2025-02-18 13-35-06.986 [Debug] (Server) onMessageReceived: Time, size: 8, id: 7103, refers: 0, sent: 9119,4106, recv: 2026896,418496
2025-02-18 13-35-07.035 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4028, refers: 0
2025-02-18 13-35-07.035 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4028, refers: 0, sent: 1125563,445844, recv: 2026896,467221
2025-02-18 13-35-07.988 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 7104, refers: 0
2025-02-18 13-35-07.988 [Debug] (Server) onMessageReceived: Time, size: 8, id: 7104, refers: 0, sent: 9120,6032, recv: 2026897,420268
2025-02-18 13-35-08.038 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4029, refers: 0
2025-02-18 13-35-08.038 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4029, refers: 0, sent: 1125564,448768, recv: 2026897,470171
2025-02-18 13-35-08.831 [Debug] (Server) Saving config
2025-02-18 13-35-08.935 [Info] (Server) onResync (mpd): 46.4454 ms
2025-02-18 13-35-08.989 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 7105, refers: 0
2025-02-18 13-35-08.989 [Debug] (Server) onMessageReceived: Time, size: 8, id: 7105, refers: 0, sent: 9121,7361, recv: 2026898,421504
2025-02-18 13-35-09.042 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4030, refers: 0
2025-02-18 13-35-09.042 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4030, refers: 0, sent: 1125565,451483, recv: 2026898,474469
2025-02-18 13-35-09.990 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 7106, refers: 0
2025-02-18 13-35-09.990 [Debug] (Server) onMessageReceived: Time, size: 8, id: 7106, refers: 0, sent: 9122,8745, recv: 2026899,422828
2025-02-18 13-35-10.045 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4031, refers: 0
2025-02-18 13-35-10.045 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4031, refers: 0, sent: 1125566,455931, recv: 2026899,477303
2025-02-18 13-35-10.992 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 7107, refers: 0
2025-02-18 13-35-10.992 [Debug] (Server) onMessageReceived: Time, size: 8, id: 7107, refers: 0, sent: 9123,10134, recv: 2026900,424349
2025-02-18 13-35-11.048 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4032, refers: 0
2025-02-18 13-35-11.048 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4032, refers: 0, sent: 1125567,458698, recv: 2026900,480134
2025-02-18 13-35-11.994 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 7108, refers: 0
2025-02-18 13-35-11.994 [Debug] (Server) onMessageReceived: Time, size: 8, id: 7108, refers: 0, sent: 9124,11972, recv: 2026901,426163
2025-02-18 13-35-12.051 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4033, refers: 0
2025-02-18 13-35-12.051 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4033, refers: 0, sent: 1125568,461599, recv: 2026901,483821
2025-02-18 13-35-12.995 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 7109, refers: 0
2025-02-18 13-35-12.996 [Debug] (Server) onMessageReceived: Time, size: 8, id: 7109, refers: 0, sent: 9125,13768, recv: 2026902,428131
2025-02-18 13-35-13.056 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4034, refers: 0
2025-02-18 13-35-13.057 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4034, refers: 0, sent: 1125569,465250, recv: 2026902,488940
2025-02-18 13-35-13.997 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 7110, refers: 0
2025-02-18 13-35-13.997 [Debug] (Server) onMessageReceived: Time, size: 8, id: 7110, refers: 0, sent: 9126,15576, recv: 2026903,429713
2025-02-18 13-35-14.060 [Debug] (StreamSessionTCP) getNextMessage: Time, size: 8, id: 4035, refers: 0
2025-02-18 13-35-14.060 [Debug] (Server) onMessageReceived: Time, size: 8, id: 4035, refers: 0, sent: 1125570,470891, recv: 2026903,492397
^C2025-02-18 13-35-14.243 [Info] (Snapserver) Received signal 2: Interrupt
2025-02-18 13-35-14.244 [Info] (Snapserver) Stopping streamServer
2025-02-18 13-35-14.244 [Info] (PcmStream) State changed: mpd, state: playing => idle
2025-02-18 13-35-14.244 [Info] (Server) onStateChanged (mpd): idle
2025-02-18 13-35-14.244 [Debug] (StreamSessionTCP) stop
2025-02-18 13-35-14.244 [Debug] (StreamSessionTCP) stopped
2025-02-18 13-35-14.244 [Debug] (StreamSessionTCP) stop
2025-02-18 13-35-14.244 [Debug] (StreamSessionTCP) stopped
2025-02-18 13-35-14.245 [Info] (Snapserver) done
2025-02-18 13-35-14.245 [Debug] (ControlSessionWS) ControlSessionWebsocket::~ControlSessionWebsocket()
2025-02-18 13-35-14.245 [Debug] (ControlSessionHTTP) ControlSessionHttp::~ControlSessionHttp()
2025-02-18 13-35-14.245 [Debug] (StreamSessionTCP) ~StreamSessionTcp
2025-02-18 13-35-14.245 [Debug] (StreamSessionTCP) stop
2025-02-18 13-35-14.245 [Debug] (StreamSessionTCP) ~StreamSessionTcp
2025-02-18 13-35-14.245 [Debug] (StreamSessionTCP) stop
2025-02-18 13-35-14.399 [Notice] (Snapserver) Snapserver terminated.

So the issue appears to be that a resync is forced every time an rpc message is received, and for some reason I have an abnormally high time value for the resync.

Things I have (blindly, and naively) attempted, but have made no difference:

  • Change sampleformat to 41000:16:2
  • Increase the chunk_ms to 40
  • Significantly increase the buffer to 4000
  • Removing encoded art data from the metadata
  • Removing all metadata (this gives me 1 significant stutter rather than 2)

@badaix
Copy link
Owner

badaix commented Feb 19, 2025

Have you tried using more threads?

@torzdf
Copy link
Author

torzdf commented Feb 19, 2025 •
edited
Loading

I just tried it now. I upped it from 4 (-1) to 12.

I would say that it might reduce the length of the stutter a bit, but not enough to not be noticeable.

If it helps any, SnapServer is running under the following conditions:

  • Virtual Machine running Debian 12
  • CPU: Intel(R) Xeon(R) CPU E5-2660 v3 @ 2.60GHz (old but is certainly beefy enough to run media encoding/decoding)
    • 12 virtual cores
  • 14GB Ram
  • Music is accessed off an NFS share, but the disks that host the files are in the same box as hosts the VM (the NFS server is the VM host).
  • SnapServer is running on the same box as MPD

Other things I have now ruled out:

  • pcm/ogg/flac/opus all display the same issue

--Edit--
Ok, I may have now found a contributing factor.

If I disconnect all clients (ie shutdown all running SnapClient instances), I still get the onResync in the logs but the value drops to single digits (obviously I cannot check for an audible stutter in this setup, but I would imagine it would be barely noticeable, if noticeable at all).

As soon as I reconnect a client, the onResync value jumps again and audible stutter is there. I am testing on 2 clients One on an ancient netbook, and the other on a modern desktop. It does not seem to matter if I connect either/both of these clients, the issue is the same.

So, perhaps I am looking in the wrong place, and it is either a client config issue, or some kind of timing issue between server and clients?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@badaix @torzdf