Dec 18 08:43:02 volumio systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Dec 18 08:43:02 volumio systemd[1]: mpd.service: Failed with result 'signal'. Dec 18 08:43:02 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 18 08:43:02 volumio systemd[1]: mpd.service: Consumed 3.236s CPU time. Dec 18 08:43:02 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 18 08:43:02 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 18 08:43:02 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 18 08:43:02 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 18 08:43:02 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 18 08:43:02 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 18 08:43:02 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 18 08:43:02 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 18 08:43:02 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 18 08:43:02 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 18 08:43:02 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 18 08:43:02 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 18 08:43:02 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 18 08:43:02 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 18 08:43:02 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 18 08:43:02 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 18 08:43:02 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 18 08:43:02 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 18 08:43:03 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 18 08:43:03 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 18 08:43:03 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 18 08:43:03 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 18 08:43:03 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 18 08:43:03 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 18 08:43:03 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 18 08:43:03 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 18 08:43:03 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 18 08:43:03 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 18 08:43:03 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 18 08:43:03 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 18 08:43:03 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 18 08:43:03 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 18 08:43:03 volumio volumio[1258]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 18 08:43:03 volumio volumio[1258]: info: Adding plugin bluetooth to MyMusic Plugins Dec 18 08:43:03 volumio volumio[1258]: info: Adding plugin multiroom to MyMusic Plugins Dec 18 08:43:03 volumio volumio[1258]: info: Adding plugin metavolumio to MyMusic Plugins Dec 18 08:43:03 volumio volumio[1258]: info: Adding plugin cd_controller to MyMusic Plugins Dec 18 08:43:03 volumio sudo[1801]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 18 08:43:03 volumio sudo[1801]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 18 08:43:03 volumio sudo[1801]: pam_unix(sudo:session): session closed for user root Dec 18 08:43:03 volumio volumio[1258]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 18 08:43:03 volumio volumio[1258]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 18 08:43:03 volumio volumio[1258]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 18 08:43:03 volumio volumio[1258]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 18 08:43:03 volumio bluealsa[827]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State Dec 18 08:43:05 volumio systemd[1]: Started rfid-player.service - RFID Card Player for Volumio. Dec 18 08:43:06 volumio mpd[1803]: 2025-12-18T08:43:06 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 18 08:43:07 volumio python[1818]: RFID Manager läuft. Web-Interface auf Port 5001. Dec 18 08:43:07 volumio python[1818]: * Serving Flask app 'app' Dec 18 08:43:07 volumio python[1818]: * Debug mode: off Dec 18 08:43:07 volumio python[1818]: Address already in use Dec 18 08:43:07 volumio python[1818]: Port 5001 is in use by another program. Either identify and stop that program, or start the server with a different port. Dec 18 08:43:07 volumio systemd[1]: rfid-player.service: Main process exited, code=exited, status=1/FAILURE Dec 18 08:43:07 volumio systemd[1]: rfid-player.service: Failed with result 'exit-code'. Dec 18 08:43:07 volumio systemd[1]: rfid-player.service: Consumed 1.451s CPU time. Dec 18 08:43:07 volumio systemd[1]: rfid-player.service: Scheduled restart job, restart counter is at 5. Dec 18 08:43:07 volumio systemd[1]: Stopped rfid-player.service - RFID Card Player for Volumio. Dec 18 08:43:07 volumio systemd[1]: rfid-player.service: Consumed 1.451s CPU time. Dec 18 08:43:07 volumio systemd[1]: Starting rfid-player.service - RFID Card Player for Volumio... Dec 18 08:43:09 volumio go-librespot[1638]: time="2025-12-18T08:43:09+01:00" level=trace msg="sent dealer ping" Dec 18 08:43:09 volumio go-librespot[1638]: time="2025-12-18T08:43:09+01:00" level=trace msg="received dealer pong" Dec 18 08:43:14 volumio volumio[1258]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 18 08:43:14 volumio volumio[1258]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 18 08:43:14 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 18 08:43:14 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 18 08:43:14 volumio volumio[1258]: info: Starting MyVolumio Remote Streaming Endpoints Dec 18 08:43:15 volumio volumio[1258]: info: MyVolumio login type: Token Dec 18 08:43:15 volumio volumio[1258]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 18 08:43:15 volumio volumio[1258]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 18 08:43:22 volumio systemd[1]: Started rfid-player.service - RFID Card Player for Volumio. Dec 18 08:43:24 volumio python[1841]: RFID Manager läuft. Web-Interface auf Port 5001. Dec 18 08:43:24 volumio python[1841]: * Serving Flask app 'app' Dec 18 08:43:24 volumio python[1841]: * Debug mode: off Dec 18 08:43:24 volumio python[1841]: Address already in use Dec 18 08:43:24 volumio python[1841]: Port 5001 is in use by another program. Either identify and stop that program, or start the server with a different port. Dec 18 08:43:24 volumio systemd[1]: rfid-player.service: Main process exited, code=exited, status=1/FAILURE Dec 18 08:43:24 volumio systemd[1]: rfid-player.service: Failed with result 'exit-code'. Dec 18 08:43:24 volumio systemd[1]: rfid-player.service: Consumed 1.382s CPU time. Dec 18 08:43:24 volumio systemd[1]: rfid-player.service: Scheduled restart job, restart counter is at 6. Dec 18 08:43:24 volumio systemd[1]: Stopped rfid-player.service - RFID Card Player for Volumio. Dec 18 08:43:24 volumio systemd[1]: rfid-player.service: Consumed 1.382s CPU time. Dec 18 08:43:24 volumio systemd[1]: Starting rfid-player.service - RFID Card Player for Volumio... Dec 18 08:43:25 volumio volumio[1258]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 18 08:43:25 volumio volumio[1258]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 18 08:43:25 volumio volumio[1258]: info: Streaming services startup Dec 18 08:43:25 volumio volumio[1258]: info: Starting Streaming Daemon Dec 18 08:43:25 volumio volumio[1258]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 18 08:43:25 volumio sudo[1858]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 18 08:43:25 volumio sudo[1858]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 18 08:43:25 volumio sudo[1858]: pam_unix(sudo:session): session closed for user root Dec 18 08:43:25 volumio volumio[1258]: info: CoreCommandRouter::volumioPlay Dec 18 08:43:25 volumio volumio[1258]: info: CoreStateMachine::play index undefined Dec 18 08:43:25 volumio volumio[1258]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 18 08:43:25 volumio volumio[1258]: info: CoreCommandRouter::volumioPlay Dec 18 08:43:25 volumio volumio[1258]: info: CoreStateMachine::play index undefined Dec 18 08:43:25 volumio volumio[1258]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 18 08:43:25 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:25 volumio volumio[1258]: info: CoreStateMachine::startPlaybackTimer Dec 18 08:43:25 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:25 volumio volumio[1258]: info: [1766043805955] ControllerSpotify::clearAddPlayTrack Dec 18 08:43:25 volumio volumio[1258]: info: Sending Spotify command with payload to local API: /player/play Dec 18 08:43:25 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:25 volumio volumio[1258]: info: CoreStateMachine::startPlaybackTimer Dec 18 08:43:25 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:25 volumio volumio[1258]: info: [1766043805986] ControllerSpotify::clearAddPlayTrack Dec 18 08:43:25 volumio volumio[1258]: info: Sending Spotify command with payload to local API: /player/play Dec 18 08:43:26 volumio volumio[1258]: error: Cannot start Volumio Streaming Daemon Dec 18 08:43:26 volumio volumio[1258]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 18 08:43:26 volumio volumio[1258]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 18 08:43:26 volumio go-librespot[1638]: time="2025-12-18T08:43:26+01:00" level=debug msg="resolved context of track" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:26 volumio go-librespot[1638]: time="2025-12-18T08:43:26+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:26 volumio go-librespot[1638]: time="2025-12-18T08:43:26+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:26 volumio go-librespot[1638]: time="2025-12-18T08:43:26+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 18 08:43:26 volumio go-librespot[1638]: time="2025-12-18T08:43:26+01:00" level=trace msg="emitting websocket event: will_play" Dec 18 08:43:26 volumio go-librespot[1638]: time="2025-12-18T08:43:26+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Dec 18 08:43:26 volumio go-librespot[1638]: time="2025-12-18T08:43:26+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 18 08:43:26 volumio go-librespot[1638]: time="2025-12-18T08:43:26+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1384" Dec 18 08:43:26 volumio go-librespot[1638]: time="2025-12-18T08:43:26+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 18 08:43:26 volumio go-librespot[1638]: time="2025-12-18T08:43:26+01:00" level=debug msg="selected format OGG_VORBIS_320 (be8082b22f985cbf2c6a3cf365ab2545ad821492)" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:26 volumio go-librespot[1638]: time="2025-12-18T08:43:26+01:00" level=debug msg="requested aes key for file be8082b22f985cbf2c6a3cf365ab2545ad821492, gid: 4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:26 volumio go-librespot[1638]: time="2025-12-18T08:43:26+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:26 volumio go-librespot[1638]: time="2025-12-18T08:43:26+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1136" Dec 18 08:43:26 volumio go-librespot[1638]: time="2025-12-18T08:43:26+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 18 08:43:26 volumio go-librespot[1638]: time="2025-12-18T08:43:26+01:00" level=debug msg="fetched first chunk of 14, total size is 6946544 bytes" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:26 volumio go-librespot[1638]: time="2025-12-18T08:43:26+01:00" level=debug msg="created new output device" Dec 18 08:43:26 volumio go-librespot[1638]: [1684] D: bluealsa-pcm.c:1538: Getting BlueALSA PCM: PLAYBACK 08:EB:ED:25:4F:D6 a2dp Dec 18 08:43:26 volumio bluealsa[827]: ../src/dbus.c:47: Called: org.bluealsa.PCM1.GetCodecs() on /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink Dec 18 08:43:26 volumio go-librespot[1638]: [1684] D: bluealsa-pcm.c:1296: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Setting constraints Dec 18 08:43:26 volumio go-librespot[1638]: [1712] D: bluealsa-pcm.c:566: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Initializing HW Dec 18 08:43:26 volumio bluealsa[827]: ../src/dbus.c:47: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink Dec 18 08:43:26 volumio bluetoothd[675]: /org/bluez/hci0/dev_08_EB_ED_25_4F_D6/fd0: fd(27) ready Dec 18 08:43:26 volumio bluealsa[827]: ../src/ba-transport.c:319: New A2DP transport: 19 Dec 18 08:43:26 volumio bluealsa[827]: ../src/ba-transport.c:320: A2DP socket MTU: 19: R:1021 W:672 Dec 18 08:43:26 volumio bluealsa[827]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State Dec 18 08:43:26 volumio bluealsa[827]: ../src/ba-transport.c:1075: Starting transport: A2DP Source (SBC) Dec 18 08:43:26 volumio bluealsa[827]: ../src/ba-transport-pcm.c:294: Created BT socket duplicate: [19]: 20 Dec 18 08:43:26 volumio bluealsa[827]: ../src/ba-transport-pcm.c:373: Created new IO thread [ba-a2dp-sbc]: A2DP Source (SBC) Dec 18 08:43:26 volumio bluealsa[827]: ../src/codec-sbc.c:278: SBC setup: 44100 Hz JointStereo allocation=Loudness blocks=16 sub-bands=8 bit-pool=53 => 327993 bps Dec 18 08:43:26 volumio bluealsa[827]: ../src/a2dp-sbc.c:191: PCM IO loop: START: a2dp_sbc_enc_thread: A2DP Source (SBC) Dec 18 08:43:26 volumio go-librespot[1638]: [1712] D: bluealsa-pcm.c:631: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: FIFO buffer size: 1024 frames Dec 18 08:43:26 volumio go-librespot[1638]: [1712] D: bluealsa-pcm.c:636: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Selected HW buffer: 10 periods x 17640 bytes == 176400 bytes Dec 18 08:43:26 volumio go-librespot[1638]: [1712] D: bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Initializing SW Dec 18 08:43:26 volumio go-librespot[1638]: [1712] D: bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Initializing SW Dec 18 08:43:26 volumio go-librespot[1638]: [1712] D: bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Initializing SW Dec 18 08:43:26 volumio go-librespot[1638]: [1712] D: bluealsa-pcm.c:717: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Prepared Dec 18 08:43:26 volumio go-librespot[1638]: time="2025-12-18T08:43:26+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 1000000 us, buffer size = 44100 frames, periods per buffer = 10 frames, PCM format = FLOAT_LE" Dec 18 08:43:26 volumio go-librespot[1638]: [1712] D: bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Initializing SW Dec 18 08:43:26 volumio go-librespot[1638]: [1712] D: bluealsa-pcm.c:428: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Stopping Dec 18 08:43:26 volumio bluealsa[827]: ../src/ba-transport-pcm.c:524: PCM drop: 15 Dec 18 08:43:26 volumio go-librespot[1638]: [1712] D: bluealsa-pcm.c:717: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Prepared Dec 18 08:43:26 volumio go-librespot[1638]: time="2025-12-18T08:43:26+01:00" level=info msg="loaded track \"Somethin' Stupid\" (paused: false, position: 0ms, duration: 162493ms, prefetched: false)" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=trace msg="scheduling prefetch in 133s" Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=trace msg="emitting websocket event: metadata" Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=trace msg="emitting websocket event: playing" Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=debug msg="resolved context of track" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:27 volumio go-librespot[1638]: [1684] D: bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Starting Dec 18 08:43:27 volumio bluealsa[827]: ../src/ba-transport-pcm.c:480: PCM resume: 15 Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=debug msg="loading track (paused: false, position: 30ms)" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:27 volumio go-librespot[1638]: [1868] D: bluealsa-pcm.c:235: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Starting IO loop: 27 Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=trace msg="emitting websocket event: will_play" Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:27 volumio volumio[1258]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","play_origin":"go-librespot"}} Dec 18 08:43:27 volumio volumio[1258]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","name":"Somethin' Stupid","artist_names":["Frank Sinatra","Nancy Sinatra"],"album_name":"The World We Knew","album_cover_url":"https://i.scdn.co/image/ab67616d00001e023e2331ff09f59ea3c87fe5d6","position":0,"duration":162493,"release_date":"year:1967 month:8","track_number":2,"disc_number":1}} Dec 18 08:43:27 volumio volumio[1258]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","resume":false,"play_origin":"go-librespot"}} Dec 18 08:43:27 volumio volumio[1258]: SPOTIFY: PUSH STATE SPOTIFY Dec 18 08:43:27 volumio volumio[1258]: SPOTIFY: {"status":"play","service":"spop","title":"Somethin' Stupid","artist":"Frank Sinatra, Nancy Sinatra","album":"The World We Knew","albumart":"https://i.scdn.co/image/ab67616d00001e023e2331ff09f59ea3c87fe5d6","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","trackType":"spotify","seek":0,"duration":162,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:27 volumio volumio[1258]: info: CoreCommandRouter::servicePushState Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=debug msg="selected format OGG_VORBIS_320 (be8082b22f985cbf2c6a3cf365ab2545ad821492)" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=debug msg="requested aes key for file be8082b22f985cbf2c6a3cf365ab2545ad821492, gid: 4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:27 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:27 volumio volumio[1258]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Somethin' Stupid","artist":"Frank Sinatra, Nancy Sinatra","album":"The World We Knew","albumart":"https://i.scdn.co/image/ab67616d00001e023e2331ff09f59ea3c87fe5d6","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","trackType":"spotify","seek":0,"duration":162,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 18 08:43:27 volumio volumio[1258]: verbose: CURRENT POSITION 0 Dec 18 08:43:27 volumio volumio[1258]: info: CoreStateMachine::syncState stateService play Dec 18 08:43:27 volumio volumio[1258]: info: CoreStateMachine::syncState currentStatus stop Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:27 volumio volumio[1258]: error: MyVolumio Custom Token format not valid, refreshing it Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=debug msg="fetched first chunk of 14, total size is 6946544 bytes" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=trace msg="seek to 30ms (diff: 30ms, samples: 1323, bytes: 0)" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:27 volumio go-librespot[1638]: [1684] D: bluealsa-pcm.c:428: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Stopping Dec 18 08:43:27 volumio go-librespot[1638]: [1868] D: bluealsa-pcm.c:171: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: IO thread cleanup Dec 18 08:43:27 volumio bluealsa[827]: ../src/ba-transport-pcm.c:524: PCM drop: 15 Dec 18 08:43:27 volumio bluealsa[827]: ../src/io.c:172: Flushed PCM samples [15]: 860 Dec 18 08:43:27 volumio go-librespot[1638]: [1684] D: bluealsa-pcm.c:717: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Prepared Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=info msg="loaded track \"Somethin' Stupid\" (paused: false, position: 30ms, duration: 162493ms, prefetched: false)" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:27 volumio volumio[1258]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","play_origin":"go-librespot"}} Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=trace msg="scheduling prefetch in 132s" Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=trace msg="emitting websocket event: metadata" Dec 18 08:43:27 volumio go-librespot[1638]: [1684] D: bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Starting Dec 18 08:43:27 volumio bluealsa[827]: ../src/ba-transport-pcm.c:480: PCM resume: 15 Dec 18 08:43:27 volumio go-librespot[1638]: [1869] D: bluealsa-pcm.c:235: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Starting IO loop: 27 Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=trace msg="emitting websocket event: playing" Dec 18 08:43:27 volumio volumio[1258]: SPOTIFY: PUSH STATE SPOTIFY Dec 18 08:43:27 volumio volumio[1258]: SPOTIFY: {"status":"play","service":"spop","title":"Somethin' Stupid","artist":"Frank Sinatra, Nancy Sinatra","album":"The World We Knew","albumart":"https://i.scdn.co/image/ab67616d00001e023e2331ff09f59ea3c87fe5d6","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","trackType":"spotify","seek":0,"duration":162,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 18 08:43:27 volumio volumio[1258]: info: CoreCommandRouter::servicePushState Dec 18 08:43:27 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:27 volumio volumio[1258]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Somethin' Stupid","artist":"Frank Sinatra, Nancy Sinatra","album":"The World We Knew","albumart":"https://i.scdn.co/image/ab67616d00001e023e2331ff09f59ea3c87fe5d6","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","trackType":"spotify","seek":0,"duration":162,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 18 08:43:27 volumio volumio[1258]: verbose: CURRENT POSITION 0 Dec 18 08:43:27 volumio volumio[1258]: info: CoreStateMachine::syncState stateService play Dec 18 08:43:27 volumio volumio[1258]: info: CoreStateMachine::syncState currentStatus play Dec 18 08:43:27 volumio volumio[1258]: info: Received an update from plugin. extracting info from payload Dec 18 08:43:27 volumio volumio[1258]: info: CoreStateMachine::pushState Dec 18 08:43:27 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:27 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 18 08:43:27 volumio volumio[1258]: info: CoreCommandRouter::volumioPushState Dec 18 08:43:27 volumio go-librespot[1638]: time="2025-12-18T08:43:27+01:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:28 volumio go-librespot[1638]: time="2025-12-18T08:43:28+01:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:28 volumio volumio[1258]: info: CoreStateMachine::pushState Dec 18 08:43:28 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:28 volumio go-librespot[1638]: time="2025-12-18T08:43:28+01:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:28 volumio volumio[1258]: info: CoreCommandRouter::volumioPushState Dec 18 08:43:28 volumio volumio[1258]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","name":"Somethin' Stupid","artist_names":["Frank Sinatra","Nancy Sinatra"],"album_name":"The World We Knew","album_cover_url":"https://i.scdn.co/image/ab67616d00001e023e2331ff09f59ea3c87fe5d6","position":30,"duration":162493,"release_date":"year:1967 month:8","track_number":2,"disc_number":1}} Dec 18 08:43:28 volumio volumio[1258]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","resume":false,"play_origin":"go-librespot"}} Dec 18 08:43:28 volumio volumio[1258]: SPOTIFY: PUSH STATE SPOTIFY Dec 18 08:43:28 volumio volumio[1258]: SPOTIFY: {"status":"play","service":"spop","title":"Somethin' Stupid","artist":"Frank Sinatra, Nancy Sinatra","album":"The World We Knew","albumart":"https://i.scdn.co/image/ab67616d00001e023e2331ff09f59ea3c87fe5d6","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","trackType":"spotify","seek":30,"duration":162,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 18 08:43:28 volumio volumio[1258]: info: CoreCommandRouter::servicePushState Dec 18 08:43:28 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:28 volumio volumio[1258]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Somethin' Stupid","artist":"Frank Sinatra, Nancy Sinatra","album":"The World We Knew","albumart":"https://i.scdn.co/image/ab67616d00001e023e2331ff09f59ea3c87fe5d6","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","trackType":"spotify","seek":30,"duration":162,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 18 08:43:28 volumio volumio[1258]: verbose: CURRENT POSITION 0 Dec 18 08:43:28 volumio volumio[1258]: info: CoreStateMachine::syncState stateService play Dec 18 08:43:28 volumio volumio[1258]: info: CoreStateMachine::syncState currentStatus play Dec 18 08:43:28 volumio volumio[1258]: info: Received an update from plugin. extracting info from payload Dec 18 08:43:28 volumio volumio[1258]: info: CoreStateMachine::pushState Dec 18 08:43:28 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:28 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 18 08:43:28 volumio volumio[1258]: info: CoreCommandRouter::volumioPushState Dec 18 08:43:28 volumio volumio[1258]: info: CoreStateMachine::pushState Dec 18 08:43:28 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:28 volumio volumio[1258]: info: CoreCommandRouter::volumioPushState Dec 18 08:43:28 volumio volumio[1258]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Dec 18 08:43:28 volumio volumio[1258]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Dec 18 08:43:29 volumio volumio[1258]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Dec 18 08:43:29 volumio volumio[1258]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Dec 18 08:43:29 volumio volumio[1258]: SPOTIFY: PUSH STATE SPOTIFY Dec 18 08:43:29 volumio volumio[1258]: SPOTIFY: {"status":"play","service":"spop","title":"Somethin' Stupid","artist":"Frank Sinatra, Nancy Sinatra","album":"The World We Knew","albumart":"https://i.scdn.co/image/ab67616d00001e023e2331ff09f59ea3c87fe5d6","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","trackType":"spotify","seek":1030,"duration":162,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 18 08:43:29 volumio volumio[1258]: info: CoreCommandRouter::servicePushState Dec 18 08:43:29 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:29 volumio volumio[1258]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Somethin' Stupid","artist":"Frank Sinatra, Nancy Sinatra","album":"The World We Knew","albumart":"https://i.scdn.co/image/ab67616d00001e023e2331ff09f59ea3c87fe5d6","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","trackType":"spotify","seek":1030,"duration":162,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 18 08:43:29 volumio volumio[1258]: verbose: CURRENT POSITION 0 Dec 18 08:43:29 volumio volumio[1258]: info: CoreStateMachine::syncState stateService play Dec 18 08:43:29 volumio volumio[1258]: info: CoreStateMachine::syncState currentStatus play Dec 18 08:43:29 volumio volumio[1258]: info: Received an update from plugin. extracting info from payload Dec 18 08:43:29 volumio volumio[1258]: info: CoreStateMachine::pushState Dec 18 08:43:29 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:29 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 18 08:43:29 volumio volumio[1258]: info: CoreCommandRouter::volumioPushState Dec 18 08:43:29 volumio volumio[1258]: info: CoreStateMachine::pushState Dec 18 08:43:29 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:29 volumio volumio[1258]: info: CoreCommandRouter::volumioPushState Dec 18 08:43:29 volumio volumio[1258]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Dec 18 08:43:29 volumio volumio[1258]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Dec 18 08:43:29 volumio volumio[1258]: info: CoreCommandRouter::volumioPause Dec 18 08:43:29 volumio volumio[1258]: info: CoreStateMachine::pause Dec 18 08:43:29 volumio volumio[1258]: info: CoreStateMachine::stPlaybackTimer Dec 18 08:43:29 volumio volumio[1258]: info: CoreStateMachine::servicePause Dec 18 08:43:29 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:29 volumio volumio[1258]: info: CoreCommandRouter::servicePause Dec 18 08:43:29 volumio volumio[1258]: info: Spotify Received pause Dec 18 08:43:29 volumio volumio[1258]: SPOTIFY: SPOTIFY PAUSE Dec 18 08:43:29 volumio volumio[1258]: SPOTIFY: {"status":"play","position":0,"title":"Somethin' Stupid","artist":"Frank Sinatra","album":"The World We Knew","albumart":"https://i.scdn.co/image/ab67616d0000b2733e2331ff09f59ea3c87fe5d6","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","trackType":"spotify","codec":"ogg","seek":1030,"duration":162,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":40,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Dec 18 08:43:29 volumio volumio[1258]: info: Sending Spotify command to local API: /player/pause Dec 18 08:43:29 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 18 08:43:30 volumio set-bt-output.sh[1870]: Output 1 (alsa) is disabled Dec 18 08:43:30 volumio set-bt-output.sh[1870]: allowed_formats="" Dec 18 08:43:30 volumio set-bt-output.sh[1870]: dop="0" Dec 18 08:43:30 volumio set-bt-output.sh[1870]: Output 2 (multiroom) is disabled Dec 18 08:43:30 volumio set-bt-output.sh[1870]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:30 volumio set-bt-output.sh[1870]: allowed_formats="" Dec 18 08:43:30 volumio set-bt-output.sh[1870]: dop="0" Dec 18 08:43:30 volumio set-bt-output.sh[1871]: Output 1 (alsa) is disabled Dec 18 08:43:30 volumio set-bt-output.sh[1871]: allowed_formats="" Dec 18 08:43:30 volumio set-bt-output.sh[1871]: dop="0" Dec 18 08:43:30 volumio set-bt-output.sh[1871]: Output 2 (multiroom) is disabled Dec 18 08:43:30 volumio set-bt-output.sh[1871]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:30 volumio set-bt-output.sh[1871]: allowed_formats="" Dec 18 08:43:30 volumio set-bt-output.sh[1871]: dop="0" Dec 18 08:43:30 volumio go-librespot[1638]: time="2025-12-18T08:43:30+01:00" level=debug msg="pause track at 2705ms" Dec 18 08:43:30 volumio go-librespot[1638]: [1684] D: bluealsa-pcm.c:428: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Stopping Dec 18 08:43:30 volumio go-librespot[1638]: [1869] D: bluealsa-pcm.c:171: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: IO thread cleanup Dec 18 08:43:30 volumio go-librespot[1638]: [1684] D: bluealsa-pcm.c:646: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Freeing HW Dec 18 08:43:30 volumio go-librespot[1638]: [1684] D: bluealsa-pcm.c:475: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Closing Dec 18 08:43:30 volumio bluealsa[827]: ../src/ba-transport-pcm.c:524: PCM drop: 15 Dec 18 08:43:30 volumio bluealsa[827]: ../src/io.c:172: Flushed PCM samples [15]: 2048 Dec 18 08:43:30 volumio bluealsa[827]: ../src/ba-transport-pcm.c:453: Closing PCM: 15 Dec 18 08:43:30 volumio bluealsa[827]: ../src/ba-transport.c:203: PCM clients check keep-alive: 0 ms Dec 18 08:43:30 volumio bluealsa[827]: ../src/ba-transport.c:203: PCM clients check keep-alive: 0 ms Dec 18 08:43:30 volumio bluealsa[827]: ../src/ba-transport.c:148: Stopping transport: No PCM clients Dec 18 08:43:30 volumio bluealsa[827]: ../src/ba-transport-pcm.c:307: Closing BT socket duplicate [19]: 20 Dec 18 08:43:30 volumio bluealsa[827]: ../src/ba-transport.c:346: Releasing A2DP transport: 19 Dec 18 08:43:30 volumio bluealsa[827]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State Dec 18 08:43:30 volumio bluealsa[827]: ../src/ba-transport.c:381: Closing A2DP transport: 19 Dec 18 08:43:30 volumio bluealsa[827]: ../src/ba-transport-pcm.c:257: Exiting IO thread [ba-a2dp-sbc]: A2DP Source (SBC) Dec 18 08:43:30 volumio go-librespot[1638]: time="2025-12-18T08:43:30+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 18 08:43:30 volumio volumio[1258]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 15 Dec 18 08:43:30 volumio go-librespot[1638]: time="2025-12-18T08:43:30+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 18 08:43:30 volumio go-librespot[1638]: time="2025-12-18T08:43:30+01:00" level=trace msg="emitting websocket event: paused" Dec 18 08:43:30 volumio volumio[1258]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","play_origin":"go-librespot"}} Dec 18 08:43:30 volumio volumio[1258]: SPOTIFY: PUSH STATE SPOTIFY Dec 18 08:43:30 volumio volumio[1258]: SPOTIFY: {"status":"pause","service":"spop","title":"Somethin' Stupid","artist":"Frank Sinatra, Nancy Sinatra","album":"The World We Knew","albumart":"https://i.scdn.co/image/ab67616d00001e023e2331ff09f59ea3c87fe5d6","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","trackType":"spotify","seek":2030,"duration":162,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 18 08:43:30 volumio volumio[1258]: info: CoreCommandRouter::servicePushState Dec 18 08:43:30 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:30 volumio volumio[1258]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Somethin' Stupid","artist":"Frank Sinatra, Nancy Sinatra","album":"The World We Knew","albumart":"https://i.scdn.co/image/ab67616d00001e023e2331ff09f59ea3c87fe5d6","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","trackType":"spotify","seek":2030,"duration":162,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 18 08:43:30 volumio volumio[1258]: verbose: CURRENT POSITION 0 Dec 18 08:43:30 volumio volumio[1258]: info: CoreStateMachine::syncState stateService pause Dec 18 08:43:30 volumio volumio[1258]: info: CoreStateMachine::syncState currentStatus pause Dec 18 08:43:30 volumio volumio[1258]: info: CoreStateMachine::pushState Dec 18 08:43:30 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:30 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 18 08:43:30 volumio volumio[1258]: info: CoreCommandRouter::volumioPushState Dec 18 08:43:30 volumio volumio[1258]: info: CoreStateMachine::stPlaybackTimer Dec 18 08:43:30 volumio volumio[1258]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Dec 18 08:43:31 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:43:31 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:31 volumio volumio[1258]: info: MyVolumio login type: Token Dec 18 08:43:32 volumio volumio[1258]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 18 08:43:33 volumio set-bt-output.sh[1874]: Output 1 (alsa) is disabled Dec 18 08:43:33 volumio set-bt-output.sh[1874]: allowed_formats="" Dec 18 08:43:33 volumio set-bt-output.sh[1874]: dop="0" Dec 18 08:43:33 volumio set-bt-output.sh[1874]: Output 2 (multiroom) is disabled Dec 18 08:43:33 volumio set-bt-output.sh[1874]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:33 volumio set-bt-output.sh[1874]: allowed_formats="" Dec 18 08:43:33 volumio set-bt-output.sh[1874]: dop="0" Dec 18 08:43:33 volumio set-bt-output.sh[1875]: Output 1 (alsa) is disabled Dec 18 08:43:33 volumio set-bt-output.sh[1875]: allowed_formats="" Dec 18 08:43:33 volumio set-bt-output.sh[1875]: dop="0" Dec 18 08:43:33 volumio set-bt-output.sh[1875]: Output 2 (multiroom) is disabled Dec 18 08:43:33 volumio set-bt-output.sh[1875]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:33 volumio set-bt-output.sh[1875]: allowed_formats="" Dec 18 08:43:33 volumio set-bt-output.sh[1875]: dop="0" Dec 18 08:43:33 volumio volumio[1258]: info: MyVolumio token set successfully Dec 18 08:43:33 volumio volumio[1258]: info: MYVOLUMIO: Adding device Dec 18 08:43:33 volumio volumio[1258]: info: MYVOLUMIO: Evaluating Server Dec 18 08:43:34 volumio volumio[1258]: info: MyVolumio status changed Dec 18 08:43:34 volumio volumio[1258]: info: Streaming services startup Dec 18 08:43:34 volumio volumio[1258]: info: Starting Streaming Daemon Dec 18 08:43:35 volumio volumio[1258]: info: Removing browser output: myVolumio user plan is not superstar Dec 18 08:43:35 volumio volumio[1258]: info: Removing audio output: Dec 18 08:43:35 volumio volumio[1258]: info: Stoppping Tunnel 1 Dec 18 08:43:35 volumio sudo[1898]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 18 08:43:35 volumio sudo[1898]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 18 08:43:35 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 18 08:43:35 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 18 08:43:35 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Dec 18 08:43:35 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 18 08:43:35 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Dec 18 08:43:35 volumio sudo[1900]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Dec 18 08:43:35 volumio volumio[1258]: info: CoreCommandRouter::volumioGetBrowseSources Dec 18 08:43:35 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 18 08:43:35 volumio sudo[1900]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 18 08:43:35 volumio volumio[1258]: info: Setting Geolocation for MyVolumio to eu10 Dec 18 08:43:35 volumio sudo[1898]: pam_unix(sudo:session): session closed for user root Dec 18 08:43:35 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 18 08:43:35 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 18 08:43:35 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 18 08:43:35 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 18 08:43:35 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 18 08:43:35 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 18 08:43:35 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 18 08:43:35 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 18 08:43:35 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 18 08:43:35 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 18 08:43:35 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 18 08:43:35 volumio sudo[1900]: pam_unix(sudo:session): session closed for user root Dec 18 08:43:35 volumio volumio[1258]: error: Cannot start Volumio Streaming Daemon Dec 18 08:43:35 volumio volumio[1258]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 18 08:43:35 volumio volumio[1258]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 18 08:43:35 volumio volumio[1258]: info: Remote SSH Stopped Dec 18 08:43:35 volumio volumio[1258]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 18 08:43:36 volumio set-bt-output.sh[1917]: Output 1 (alsa) is disabled Dec 18 08:43:36 volumio set-bt-output.sh[1917]: allowed_formats="" Dec 18 08:43:36 volumio set-bt-output.sh[1917]: dop="0" Dec 18 08:43:36 volumio set-bt-output.sh[1917]: Output 2 (multiroom) is disabled Dec 18 08:43:36 volumio set-bt-output.sh[1917]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:36 volumio set-bt-output.sh[1917]: allowed_formats="" Dec 18 08:43:36 volumio set-bt-output.sh[1917]: dop="0" Dec 18 08:43:36 volumio set-bt-output.sh[1918]: Output 1 (alsa) is disabled Dec 18 08:43:36 volumio set-bt-output.sh[1918]: allowed_formats="" Dec 18 08:43:36 volumio set-bt-output.sh[1918]: dop="0" Dec 18 08:43:36 volumio set-bt-output.sh[1918]: Output 2 (multiroom) is disabled Dec 18 08:43:36 volumio set-bt-output.sh[1918]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:36 volumio set-bt-output.sh[1918]: allowed_formats="" Dec 18 08:43:36 volumio set-bt-output.sh[1918]: dop="0" Dec 18 08:43:36 volumio volumio[1258]: info: Updating MyVolumio device info Dec 18 08:43:36 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 18 08:43:36 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 18 08:43:36 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 18 08:43:37 volumio volumio[1258]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 18 08:43:39 volumio set-bt-output.sh[1923]: Output 1 (alsa) is disabled Dec 18 08:43:39 volumio set-bt-output.sh[1923]: allowed_formats="" Dec 18 08:43:39 volumio set-bt-output.sh[1923]: dop="0" Dec 18 08:43:39 volumio set-bt-output.sh[1923]: Output 2 (multiroom) is disabled Dec 18 08:43:39 volumio set-bt-output.sh[1923]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:39 volumio set-bt-output.sh[1923]: allowed_formats="" Dec 18 08:43:39 volumio set-bt-output.sh[1923]: dop="0" Dec 18 08:43:39 volumio set-bt-output.sh[1924]: Output 1 (alsa) is disabled Dec 18 08:43:39 volumio set-bt-output.sh[1924]: allowed_formats="" Dec 18 08:43:39 volumio set-bt-output.sh[1924]: dop="0" Dec 18 08:43:39 volumio set-bt-output.sh[1924]: Output 2 (multiroom) is disabled Dec 18 08:43:39 volumio set-bt-output.sh[1924]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:39 volumio set-bt-output.sh[1924]: allowed_formats="" Dec 18 08:43:39 volumio set-bt-output.sh[1924]: dop="0" Dec 18 08:43:39 volumio go-librespot[1638]: time="2025-12-18T08:43:39+01:00" level=trace msg="sent dealer ping" Dec 18 08:43:39 volumio go-librespot[1638]: time="2025-12-18T08:43:39+01:00" level=trace msg="received dealer pong" Dec 18 08:43:39 volumio systemd[1]: Started rfid-player.service - RFID Card Player for Volumio. Dec 18 08:43:39 volumio volumio[1258]: info: MYVOLUMIO: Adding device Dec 18 08:43:39 volumio volumio[1258]: info: MYVOLUMIO: Evaluating Server Dec 18 08:43:40 volumio volumio[1258]: info: CoreCommandRouter::volumioPlay Dec 18 08:43:40 volumio volumio[1258]: info: CoreStateMachine::play index undefined Dec 18 08:43:40 volumio volumio[1258]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 18 08:43:40 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:40 volumio volumio[1258]: info: CoreStateMachine::startPlaybackTimer Dec 18 08:43:40 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:40 volumio volumio[1258]: info: Spotify Resume Dec 18 08:43:40 volumio volumio[1258]: info: Sending Spotify command to local API: /player/resume Dec 18 08:43:41 volumio python[1926]: RFID Manager läuft. Web-Interface auf Port 5001. Dec 18 08:43:41 volumio python[1926]: * Serving Flask app 'app' Dec 18 08:43:41 volumio python[1926]: * Debug mode: off Dec 18 08:43:41 volumio python[1926]: Address already in use Dec 18 08:43:41 volumio python[1926]: Port 5001 is in use by another program. Either identify and stop that program, or start the server with a different port. Dec 18 08:43:41 volumio systemd[1]: rfid-player.service: Main process exited, code=exited, status=1/FAILURE Dec 18 08:43:41 volumio systemd[1]: rfid-player.service: Failed with result 'exit-code'. Dec 18 08:43:41 volumio systemd[1]: rfid-player.service: Consumed 1.421s CPU time. Dec 18 08:43:41 volumio systemd[1]: rfid-player.service: Scheduled restart job, restart counter is at 7. Dec 18 08:43:41 volumio systemd[1]: Stopped rfid-player.service - RFID Card Player for Volumio. Dec 18 08:43:41 volumio systemd[1]: rfid-player.service: Consumed 1.421s CPU time. Dec 18 08:43:41 volumio systemd[1]: Starting rfid-player.service - RFID Card Player for Volumio... Dec 18 08:43:41 volumio go-librespot[1638]: time="2025-12-18T08:43:41+01:00" level=trace msg="seek to 2705ms (diff: 115ms, samples: 119290, bytes: 114737)" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:41 volumio go-librespot[1638]: [1684] D: bluealsa-pcm.c:1538: Getting BlueALSA PCM: PLAYBACK 08:EB:ED:25:4F:D6 a2dp Dec 18 08:43:41 volumio bluealsa[827]: ../src/dbus.c:47: Called: org.bluealsa.PCM1.GetCodecs() on /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink Dec 18 08:43:41 volumio go-librespot[1638]: [1684] D: bluealsa-pcm.c:1296: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Setting constraints Dec 18 08:43:41 volumio go-librespot[1638]: [1682] D: bluealsa-pcm.c:566: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Initializing HW Dec 18 08:43:41 volumio bluealsa[827]: ../src/dbus.c:47: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink Dec 18 08:43:41 volumio bluealsa[827]: ../src/ba-transport.c:319: New A2DP transport: 19 Dec 18 08:43:41 volumio bluealsa[827]: ../src/ba-transport.c:320: A2DP socket MTU: 19: R:1021 W:672 Dec 18 08:43:41 volumio bluealsa[827]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State Dec 18 08:43:41 volumio bluealsa[827]: ../src/ba-transport.c:1075: Starting transport: A2DP Source (SBC) Dec 18 08:43:41 volumio bluealsa[827]: ../src/ba-transport-pcm.c:294: Created BT socket duplicate: [19]: 20 Dec 18 08:43:41 volumio bluealsa[827]: ../src/codec-sbc.c:278: SBC setup: 44100 Hz JointStereo allocation=Loudness blocks=16 sub-bands=8 bit-pool=53 => 327993 bps Dec 18 08:43:41 volumio bluealsa[827]: ../src/a2dp-sbc.c:191: PCM IO loop: START: a2dp_sbc_enc_thread: A2DP Source (SBC) Dec 18 08:43:41 volumio bluealsa[827]: ../src/ba-transport-pcm.c:373: Created new IO thread [ba-a2dp-sbc]: A2DP Source (SBC) Dec 18 08:43:41 volumio go-librespot[1638]: [1682] D: bluealsa-pcm.c:631: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: FIFO buffer size: 1024 frames Dec 18 08:43:41 volumio go-librespot[1638]: [1682] D: bluealsa-pcm.c:636: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Selected HW buffer: 10 periods x 17640 bytes == 176400 bytes Dec 18 08:43:41 volumio go-librespot[1638]: [1682] D: bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Initializing SW Dec 18 08:43:41 volumio go-librespot[1638]: [1682] D: bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Initializing SW Dec 18 08:43:41 volumio go-librespot[1638]: [1682] D: bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Initializing SW Dec 18 08:43:41 volumio go-librespot[1638]: [1682] D: bluealsa-pcm.c:717: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Prepared Dec 18 08:43:41 volumio go-librespot[1638]: time="2025-12-18T08:43:41+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 1000000 us, buffer size = 44100 frames, periods per buffer = 10 frames, PCM format = FLOAT_LE" Dec 18 08:43:41 volumio go-librespot[1638]: [1682] D: bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Initializing SW Dec 18 08:43:41 volumio go-librespot[1638]: time="2025-12-18T08:43:41+01:00" level=debug msg="resume track at 2575ms" Dec 18 08:43:41 volumio go-librespot[1638]: [1684] D: bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Starting Dec 18 08:43:41 volumio go-librespot[1638]: [1947] D: bluealsa-pcm.c:235: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Starting IO loop: 25 Dec 18 08:43:41 volumio bluealsa[827]: ../src/ba-transport-pcm.c:480: PCM resume: 15 Dec 18 08:43:41 volumio go-librespot[1638]: time="2025-12-18T08:43:41+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 18 08:43:41 volumio go-librespot[1638]: time="2025-12-18T08:43:41+01:00" level=trace msg="scheduling prefetch in 130s" Dec 18 08:43:41 volumio go-librespot[1638]: time="2025-12-18T08:43:41+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 18 08:43:41 volumio go-librespot[1638]: time="2025-12-18T08:43:41+01:00" level=trace msg="emitting websocket event: playing" Dec 18 08:43:41 volumio volumio[1258]: info: Setting Geolocation for MyVolumio to eu6 Dec 18 08:43:41 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 18 08:43:41 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 18 08:43:41 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 18 08:43:42 volumio volumio[1258]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","resume":true,"play_origin":"go-librespot"}} Dec 18 08:43:42 volumio volumio[1258]: SPOTIFY: PUSH STATE SPOTIFY Dec 18 08:43:42 volumio volumio[1258]: SPOTIFY: {"status":"play","service":"spop","title":"Somethin' Stupid","artist":"Frank Sinatra, Nancy Sinatra","album":"The World We Knew","albumart":"https://i.scdn.co/image/ab67616d00001e023e2331ff09f59ea3c87fe5d6","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","trackType":"spotify","seek":2030,"duration":162,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 18 08:43:42 volumio volumio[1258]: info: CoreCommandRouter::servicePushState Dec 18 08:43:42 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:42 volumio volumio[1258]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Somethin' Stupid","artist":"Frank Sinatra, Nancy Sinatra","album":"The World We Knew","albumart":"https://i.scdn.co/image/ab67616d00001e023e2331ff09f59ea3c87fe5d6","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","trackType":"spotify","seek":2030,"duration":162,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 18 08:43:42 volumio volumio[1258]: verbose: CURRENT POSITION 0 Dec 18 08:43:42 volumio volumio[1258]: info: CoreStateMachine::syncState stateService play Dec 18 08:43:42 volumio volumio[1258]: info: CoreStateMachine::syncState currentStatus pause Dec 18 08:43:42 volumio volumio[1258]: info: CoreStateMachine::pushState Dec 18 08:43:42 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:42 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 18 08:43:42 volumio volumio[1258]: info: CoreCommandRouter::volumioPushState Dec 18 08:43:42 volumio set-bt-output.sh[1948]: Output 1 (alsa) is disabled Dec 18 08:43:42 volumio set-bt-output.sh[1948]: allowed_formats="" Dec 18 08:43:42 volumio set-bt-output.sh[1948]: dop="0" Dec 18 08:43:42 volumio set-bt-output.sh[1948]: Output 2 (multiroom) is disabled Dec 18 08:43:42 volumio set-bt-output.sh[1948]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:42 volumio set-bt-output.sh[1948]: allowed_formats="" Dec 18 08:43:42 volumio set-bt-output.sh[1948]: dop="0" Dec 18 08:43:42 volumio set-bt-output.sh[1949]: Output 1 (alsa) is disabled Dec 18 08:43:42 volumio set-bt-output.sh[1949]: allowed_formats="" Dec 18 08:43:42 volumio set-bt-output.sh[1949]: dop="0" Dec 18 08:43:42 volumio set-bt-output.sh[1949]: Output 2 (multiroom) is disabled Dec 18 08:43:42 volumio set-bt-output.sh[1949]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:42 volumio set-bt-output.sh[1949]: allowed_formats="" Dec 18 08:43:42 volumio set-bt-output.sh[1949]: dop="0" Dec 18 08:43:42 volumio volumio[1258]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Dec 18 08:43:42 volumio volumio[1258]: SPOTIFY: PUSH STATE SPOTIFY Dec 18 08:43:42 volumio volumio[1258]: SPOTIFY: {"status":"play","service":"spop","title":"Somethin' Stupid","artist":"Frank Sinatra, Nancy Sinatra","album":"The World We Knew","albumart":"https://i.scdn.co/image/ab67616d00001e023e2331ff09f59ea3c87fe5d6","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","trackType":"spotify","seek":2030,"duration":162,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 18 08:43:42 volumio volumio[1258]: info: CoreCommandRouter::servicePushState Dec 18 08:43:42 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:42 volumio volumio[1258]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Somethin' Stupid","artist":"Frank Sinatra, Nancy Sinatra","album":"The World We Knew","albumart":"https://i.scdn.co/image/ab67616d00001e023e2331ff09f59ea3c87fe5d6","uri":"spotify:track:4feXcsElKIVsGwkbnTHAfV","trackType":"spotify","seek":2030,"duration":162,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 18 08:43:42 volumio volumio[1258]: verbose: CURRENT POSITION 0 Dec 18 08:43:42 volumio volumio[1258]: info: CoreStateMachine::syncState stateService play Dec 18 08:43:42 volumio volumio[1258]: info: CoreStateMachine::syncState currentStatus play Dec 18 08:43:42 volumio volumio[1258]: info: Received an update from plugin. extracting info from payload Dec 18 08:43:42 volumio volumio[1258]: info: CoreStateMachine::pushState Dec 18 08:43:42 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:42 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 18 08:43:42 volumio volumio[1258]: info: CoreCommandRouter::volumioPushState Dec 18 08:43:42 volumio volumio[1258]: info: CoreStateMachine::pushState Dec 18 08:43:42 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:42 volumio volumio[1258]: info: CoreCommandRouter::volumioPushState Dec 18 08:43:42 volumio volumio[1258]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Dec 18 08:43:42 volumio volumio[1258]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Dec 18 08:43:42 volumio volumio[1258]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 18 08:43:42 volumio volumio[1258]: info: Updating MyVolumio device info Dec 18 08:43:42 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 18 08:43:42 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 18 08:43:42 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 18 08:43:43 volumio volumio[1258]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 18 08:43:45 volumio set-bt-output.sh[1951]: Output 1 (alsa) is disabled Dec 18 08:43:45 volumio set-bt-output.sh[1951]: allowed_formats="" Dec 18 08:43:45 volumio set-bt-output.sh[1951]: dop="0" Dec 18 08:43:45 volumio set-bt-output.sh[1951]: Output 2 (multiroom) is disabled Dec 18 08:43:45 volumio set-bt-output.sh[1951]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:45 volumio set-bt-output.sh[1951]: allowed_formats="" Dec 18 08:43:45 volumio set-bt-output.sh[1951]: dop="0" Dec 18 08:43:45 volumio set-bt-output.sh[1952]: Output 1 (alsa) is disabled Dec 18 08:43:45 volumio set-bt-output.sh[1952]: allowed_formats="" Dec 18 08:43:45 volumio set-bt-output.sh[1952]: dop="0" Dec 18 08:43:45 volumio set-bt-output.sh[1952]: Output 2 (multiroom) is disabled Dec 18 08:43:45 volumio set-bt-output.sh[1952]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:45 volumio set-bt-output.sh[1952]: allowed_formats="" Dec 18 08:43:45 volumio set-bt-output.sh[1952]: dop="0" Dec 18 08:43:45 volumio volumio[1258]: error: MyVolumio Plugin failed to authenticate in a timely fashion Dec 18 08:43:45 volumio volumio[1258]: info: Completed starting MyVolumio Plugin Dec 18 08:43:45 volumio volumio[1258]: [Metrics] CommandRouter: 117s 737.51ms Dec 18 08:43:45 volumio volumio[1258]: info: CoreCommandRouter::volumiosetStartupVolume Dec 18 08:43:45 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 18 08:43:45 volumio volumio[1258]: info: VolumeController:: Setting startup Volume 40 Dec 18 08:43:45 volumio volumio[1258]: info: VolumeController::SetAlsaVolume40 Dec 18 08:43:45 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 18 08:43:45 volumio volumio[1258]: info: CoreCommandRouter::Close All Modals sent Dec 18 08:43:45 volumio volumio[1258]: info: CoreCommandRouter::Close All Modals sent Dec 18 08:43:45 volumio volumio[1258]: info: CoreStateMachine::pushState Dec 18 08:43:45 volumio bluealsa[827]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: Volume Dec 18 08:43:45 volumio bluealsa[827]: bluez.c:1498: Skipping A2DP volume update: 32 Dec 18 08:43:45 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:43:45 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 18 08:43:45 volumio volumio[1258]: info: CoreCommandRouter::volumioPushState Dec 18 08:43:46 volumio volumio[1258]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Dec 18 08:43:46 volumio bluealsa[827]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: Volume Dec 18 08:43:46 volumio bluealsa[827]: bluez.c:1498: Skipping A2DP volume update: 40 Dec 18 08:43:46 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Dec 18 08:43:46 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 18 08:43:46 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Dec 18 08:43:48 volumio set-bt-output.sh[1974]: Output 1 (alsa) is disabled Dec 18 08:43:48 volumio set-bt-output.sh[1974]: allowed_formats="" Dec 18 08:43:48 volumio set-bt-output.sh[1974]: dop="0" Dec 18 08:43:48 volumio set-bt-output.sh[1974]: Output 2 (multiroom) is disabled Dec 18 08:43:48 volumio set-bt-output.sh[1974]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:48 volumio set-bt-output.sh[1974]: allowed_formats="" Dec 18 08:43:48 volumio set-bt-output.sh[1974]: dop="0" Dec 18 08:43:48 volumio set-bt-output.sh[1975]: Output 1 (alsa) is disabled Dec 18 08:43:48 volumio set-bt-output.sh[1975]: allowed_formats="" Dec 18 08:43:48 volumio set-bt-output.sh[1975]: dop="0" Dec 18 08:43:48 volumio set-bt-output.sh[1975]: Output 2 (multiroom) is disabled Dec 18 08:43:48 volumio set-bt-output.sh[1975]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:48 volumio set-bt-output.sh[1975]: allowed_formats="" Dec 18 08:43:48 volumio set-bt-output.sh[1975]: dop="0" Dec 18 08:43:48 volumio volumio[1258]: info: Cannot play startup sound: Error: Command failed: /usr/bin/aplay -D volumio /volumio/app/startup.wav Dec 18 08:43:48 volumio volumio[1258]: Playing WAVE '/volumio/app/startup.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo Dec 18 08:43:48 volumio volumio[1258]: aplay: xrun:1636: status error: Broken pipe Dec 18 08:43:49 volumio bluealsa[827]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: Volume Dec 18 08:43:49 volumio bluealsa[827]: bluez.c:1498: Skipping A2DP volume update: 49 Dec 18 08:43:50 volumio go-librespot[1638]: time="2025-12-18T08:43:50+01:00" level=debug msg="fetched chunk 4/13, size: 524288" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:43:51 volumio set-bt-output.sh[1977]: Output 1 (alsa) is disabled Dec 18 08:43:51 volumio set-bt-output.sh[1977]: allowed_formats="" Dec 18 08:43:51 volumio set-bt-output.sh[1977]: dop="0" Dec 18 08:43:51 volumio set-bt-output.sh[1977]: Output 2 (multiroom) is disabled Dec 18 08:43:51 volumio set-bt-output.sh[1977]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:51 volumio set-bt-output.sh[1977]: allowed_formats="" Dec 18 08:43:51 volumio set-bt-output.sh[1977]: dop="0" Dec 18 08:43:51 volumio set-bt-output.sh[1978]: Output 1 (alsa) is disabled Dec 18 08:43:51 volumio set-bt-output.sh[1978]: allowed_formats="" Dec 18 08:43:51 volumio set-bt-output.sh[1978]: dop="0" Dec 18 08:43:51 volumio set-bt-output.sh[1978]: Output 2 (multiroom) is disabled Dec 18 08:43:51 volumio set-bt-output.sh[1978]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:51 volumio set-bt-output.sh[1978]: allowed_formats="" Dec 18 08:43:51 volumio set-bt-output.sh[1978]: dop="0" Dec 18 08:43:52 volumio volumio[1258]: info: BOOT COMPLETED Dec 18 08:43:54 volumio set-bt-output.sh[1983]: Output 1 (alsa) is disabled Dec 18 08:43:54 volumio set-bt-output.sh[1983]: allowed_formats="" Dec 18 08:43:54 volumio set-bt-output.sh[1983]: dop="0" Dec 18 08:43:54 volumio set-bt-output.sh[1983]: Output 2 (multiroom) is disabled Dec 18 08:43:54 volumio set-bt-output.sh[1983]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:54 volumio set-bt-output.sh[1983]: allowed_formats="" Dec 18 08:43:54 volumio set-bt-output.sh[1983]: dop="0" Dec 18 08:43:54 volumio set-bt-output.sh[1984]: Output 1 (alsa) is disabled Dec 18 08:43:54 volumio set-bt-output.sh[1984]: allowed_formats="" Dec 18 08:43:54 volumio set-bt-output.sh[1984]: dop="0" Dec 18 08:43:54 volumio set-bt-output.sh[1984]: Output 2 (multiroom) is disabled Dec 18 08:43:54 volumio set-bt-output.sh[1984]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:54 volumio set-bt-output.sh[1984]: allowed_formats="" Dec 18 08:43:54 volumio set-bt-output.sh[1984]: dop="0" Dec 18 08:43:56 volumio systemd[1]: Started rfid-player.service - RFID Card Player for Volumio. Dec 18 08:43:56 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 18 08:43:56 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 18 08:43:57 volumio set-bt-output.sh[2001]: Output 1 (alsa) is disabled Dec 18 08:43:57 volumio set-bt-output.sh[2001]: allowed_formats="" Dec 18 08:43:57 volumio set-bt-output.sh[2001]: dop="0" Dec 18 08:43:57 volumio set-bt-output.sh[2001]: Output 2 (multiroom) is disabled Dec 18 08:43:57 volumio set-bt-output.sh[2001]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:57 volumio set-bt-output.sh[2001]: allowed_formats="" Dec 18 08:43:57 volumio set-bt-output.sh[2001]: dop="0" Dec 18 08:43:57 volumio set-bt-output.sh[2002]: Output 1 (alsa) is disabled Dec 18 08:43:57 volumio set-bt-output.sh[2002]: allowed_formats="" Dec 18 08:43:57 volumio set-bt-output.sh[2002]: dop="0" Dec 18 08:43:57 volumio set-bt-output.sh[2002]: Output 2 (multiroom) is disabled Dec 18 08:43:57 volumio set-bt-output.sh[2002]: Output 3 (Bluetooth Speaker) is enabled Dec 18 08:43:57 volumio set-bt-output.sh[2002]: allowed_formats="" Dec 18 08:43:57 volumio set-bt-output.sh[2002]: dop="0" Dec 18 08:43:57 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 18 08:43:57 volumio sudo[1505]: pam_unix(sudo:session): session closed for user root Dec 18 08:43:57 volumio sudo[1516]: pam_unix(sudo:session): session closed for user root Dec 18 08:43:57 volumio sudo[1700]: pam_unix(sudo:session): session closed for user root Dec 18 08:43:57 volumio systemd[1]: Started cdplayer_stream.service - CD → HTTP streamer (Plugin). Dec 18 08:43:57 volumio systemd[1]: Started mpd-bt-watchdog.service - MPD Bluetooth Output Watchdog. Dec 18 08:43:57 volumio sudo[1575]: pam_unix(sudo:session): session closed for user root Dec 18 08:43:57 volumio systemd[1]: Started mpd_oled_plugin.service - MPD OLED Plugin. Dec 18 08:43:57 volumio systemd[1]: Starting volumio-bt-output.service - Set Bluetooth Output for Volumio... Dec 18 08:43:57 volumio sudo[1584]: pam_unix(sudo:session): session closed for user root Dec 18 08:43:58 volumio python[2000]: RFID Manager läuft. Web-Interface auf Port 5001. Dec 18 08:43:58 volumio python[2000]: * Serving Flask app 'app' Dec 18 08:43:58 volumio python[2000]: * Debug mode: off Dec 18 08:43:58 volumio python[2000]: Address already in use Dec 18 08:43:58 volumio python[2000]: Port 5001 is in use by another program. Either identify and stop that program, or start the server with a different port. Dec 18 08:43:58 volumio volumio[1258]: info: [MPD_OLED Plugin] Started mpd_oled_plugin service Dec 18 08:43:58 volumio volumio[1258]: info: [CDPlayer]: Daemon service started Dec 18 08:43:59 volumio systemd[1]: rfid-player.service: Main process exited, code=exited, status=1/FAILURE Dec 18 08:43:59 volumio systemd[1]: rfid-player.service: Failed with result 'exit-code'. Dec 18 08:43:59 volumio systemd[1]: rfid-player.service: Consumed 1.568s CPU time. Dec 18 08:43:59 volumio systemd[1]: rfid-player.service: Scheduled restart job, restart counter is at 8. Dec 18 08:43:59 volumio systemd[1]: Stopped rfid-player.service - RFID Card Player for Volumio. Dec 18 08:43:59 volumio systemd[1]: rfid-player.service: Consumed 1.568s CPU time. Dec 18 08:43:59 volumio systemd[1]: Starting rfid-player.service - RFID Card Player for Volumio... Dec 18 08:44:00 volumio volumio[1258]: error: MPD error: The expression evaluated to a falsy value: Dec 18 08:44:00 volumio volumio[1258]: assert.ok(self.idling) Dec 18 08:44:00 volumio volumio[1258]: error: The expression evaluated to a falsy value: Dec 18 08:44:00 volumio volumio[1258]: assert.ok(self.idling) Dec 18 08:44:00 volumio volumio[1258]: error: MPD error: The expression evaluated to a falsy value: Dec 18 08:44:00 volumio volumio[1258]: assert.ok(self.idling) Dec 18 08:44:00 volumio volumio[1258]: error: The expression evaluated to a falsy value: Dec 18 08:44:00 volumio volumio[1258]: assert.ok(self.idling) Dec 18 08:44:00 volumio volumio[1258]: info: MPD running with PID1803 Dec 18 08:44:00 volumio volumio[1258]: ,establishing connection Dec 18 08:44:00 volumio volumio[1258]: error: updateQueue error: null Dec 18 08:44:00 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:00 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:00 volumio node[2003]: CD HTTP @ http://127.0.0.1:8088/wav/track/:n Dec 18 08:44:00 volumio volumio[1258]: error: updateQueue error: null Dec 18 08:44:00 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:00 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:00 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:00 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:00 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:00 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:01 volumio volumio[1258]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 18 08:44:01 volumio sudo[2028]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 18 08:44:01 volumio sudo[2028]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 18 08:44:01 volumio sudo[2025]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 18 08:44:01 volumio sudo[2025]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 18 08:44:01 volumio sudo[2032]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 18 08:44:02 volumio sudo[2032]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 18 08:44:02 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 18 08:44:02 volumio mpd_monitor.sh[2033]: MPD Monitor Service: Starting MPD Monitor Service Dec 18 08:44:02 volumio sudo[2025]: pam_unix(sudo:session): session closed for user root Dec 18 08:44:02 volumio sudo[2028]: pam_unix(sudo:session): session closed for user root Dec 18 08:44:02 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:02 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:02 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 18 08:44:02 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 18 08:44:02 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 18 08:44:02 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 18 08:44:02 volumio sudo[2032]: pam_unix(sudo:session): session closed for user root Dec 18 08:44:02 volumio mpd_monitor.sh[2038]: MPD Monitor Service: Starting MPD Monitor Service Dec 18 08:44:02 volumio volumio[1258]: info: Successfully started MPD Monitor Dec 18 08:44:02 volumio volumio[1258]: info: Successfully started MPD Monitor Dec 18 08:44:02 volumio volumio[1258]: info: Successfully started MPD Monitor Dec 18 08:44:02 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:02 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:02 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:02 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:02 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:02 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:03 volumio go-librespot[1638]: time="2025-12-18T08:44:03+01:00" level=debug msg="fetched chunk 5/13, size: 524288" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:44:03 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:03 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:03 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:03 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:03 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:03 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:04 volumio volumio[1258]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 18 08:44:04 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:04 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:04 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:04 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:04 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:04 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:05 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:05 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:05 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:05 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:05 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:05 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:05 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:05 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:05 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:05 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:06 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:06 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:06 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:06 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:06 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:06 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:06 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:06 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:07 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:07 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:07 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:07 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:07 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:07 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:07 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:07 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:08 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:08 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:08 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:08 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:08 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:08 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:08 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:08 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:09 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:09 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:09 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:09 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:09 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:09 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:09 volumio go-librespot[1638]: time="2025-12-18T08:44:09+01:00" level=trace msg="sent dealer ping" Dec 18 08:44:09 volumio go-librespot[1638]: time="2025-12-18T08:44:09+01:00" level=trace msg="received dealer pong" Dec 18 08:44:09 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:09 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:09 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:09 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:10 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:10 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:10 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:10 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:10 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:10 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:10 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:10 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:11 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:11 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:11 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:11 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:11 volumio volumio[1258]: info: CALLMETHOD: audio_interface cassette-emulator saveConfig [object Object] Dec 18 08:44:11 volumio volumio[1258]: info: CoreCommandRouter::executeOnPlugin: cassette-emulator , saveConfig Dec 18 08:44:11 volumio volumio[1258]: info: Removing Cassette effect... Dec 18 08:44:11 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:11 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:12 volumio sudo[2063]: pam_unix(sudo:auth): conversation failed Dec 18 08:44:12 volumio sudo[2063]: pam_unix(sudo:auth): auth could not identify password for [volumio] Dec 18 08:44:12 volumio volumio[1258]: info: CoreCommandRouter::volumioGetState Dec 18 08:44:12 volumio volumio[1258]: info: CorePlayQueue::getTrack 0 Dec 18 08:44:12 volumio volumio[1258]: warn: Could not restore backup: Error: Command failed: sudo cp /etc/mpd.conf.backup /etc/mpd.conf Dec 18 08:44:12 volumio volumio[1258]: sudo: a terminal is required to read the password; either use the -S option to read from standard input or configure an askpass helper Dec 18 08:44:12 volumio volumio[1258]: sudo: a password is required Dec 18 08:44:12 volumio volumio[1258]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 18 08:44:12 volumio volumio[1258]: TypeError: this.commandRouter.volumioRestart is not a function Dec 18 08:44:12 volumio volumio[1258]: at /data/plugins/audio_interface/cassette-emulator/index.js:252:28 Dec 18 08:44:12 volumio volumio[1258]: at ChildProcess.exithandler (node:child_process:429:5) Dec 18 08:44:12 volumio volumio[1258]: at ChildProcess.emit (node:events:514:28) Dec 18 08:44:12 volumio volumio[1258]: at maybeClose (node:internal/child_process:1105:16) Dec 18 08:44:12 volumio volumio[1258]: at Socket. (node:internal/child_process:457:11) Dec 18 08:44:12 volumio volumio[1258]: at Socket.emit (node:events:514:28) Dec 18 08:44:12 volumio volumio[1258]: at Pipe. (node:net:337:12) Dec 18 08:44:12 volumio volumio[1258]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 18 08:44:14 volumio systemd[1]: Started rfid-player.service - RFID Card Player for Volumio. Dec 18 08:44:15 volumio go-librespot[1638]: time="2025-12-18T08:44:15+01:00" level=debug msg="fetched chunk 6/13, size: 524288" uri="spotify:track:4feXcsElKIVsGwkbnTHAfV" Dec 18 08:44:15 volumio python[2078]: RFID Manager läuft. Web-Interface auf Port 5001. Dec 18 08:44:15 volumio python[2078]: * Serving Flask app 'app' Dec 18 08:44:15 volumio python[2078]: * Debug mode: off Dec 18 08:44:15 volumio python[2078]: Address already in use Dec 18 08:44:15 volumio python[2078]: Port 5001 is in use by another program. Either identify and stop that program, or start the server with a different port. Dec 18 08:44:16 volumio systemd[1]: rfid-player.service: Main process exited, code=exited, status=1/FAILURE Dec 18 08:44:16 volumio systemd[1]: rfid-player.service: Failed with result 'exit-code'. Dec 18 08:44:16 volumio systemd[1]: rfid-player.service: Consumed 1.564s CPU time. Dec 18 08:44:16 volumio systemd[1]: rfid-player.service: Scheduled restart job, restart counter is at 9. Dec 18 08:44:16 volumio systemd[1]: Stopped rfid-player.service - RFID Card Player for Volumio. Dec 18 08:44:16 volumio systemd[1]: rfid-player.service: Consumed 1.564s CPU time. Dec 18 08:44:16 volumio systemd[1]: Starting rfid-player.service - RFID Card Player for Volumio... Dec 18 08:44:24 volumio sudo[2104]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-18 08:43' Dec 18 08:44:24 volumio sudo[2104]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"