Mar 25 16:57:02 dining-room upmpdcli[1714]: writing RSA key Mar 25 16:57:04 dining-room volumio[1139]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Mar 25 16:57:04 dining-room volumio[1139]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Mar 25 16:57:04 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 16:57:04 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 16:57:04 dining-room volumio[1139]: info: Starting MyVolumio Remote Streaming Endpoints Mar 25 16:57:04 dining-room volumio[1139]: info: MyVolumio login type: Token Mar 25 16:57:04 dining-room volumio[1139]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Mar 25 16:57:04 dining-room volumio[1139]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Mar 25 16:57:09 dining-room volumio[1139]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Mar 25 16:57:09 dining-room volumio[1139]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Mar 25 16:57:09 dining-room volumio[1139]: info: Streaming services startup Mar 25 16:57:09 dining-room volumio[1139]: info: Starting Streaming Daemon Mar 25 16:57:09 dining-room volumio[1139]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Mar 25 16:57:09 dining-room sudo[1722]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Mar 25 16:57:09 dining-room sudo[1722]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 16:57:09 dining-room volumio[1139]: info: Initializing connection to go-librespot Websocket Mar 25 16:57:09 dining-room sudo[1722]: pam_unix(sudo:session): session closed for user root Mar 25 16:57:09 dining-room volumio[1139]: error: Cannot start Volumio Streaming Daemon Mar 25 16:57:09 dining-room volumio[1139]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Mar 25 16:57:09 dining-room volumio[1139]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Mar 25 16:57:09 dining-room go-librespot[1591]: time="2026-03-25T16:57:09+13:00" level=debug msg="new websocket client" Mar 25 16:57:09 dining-room volumio[1139]: info: Connection to go-librespot Websocket established Mar 25 16:57:10 dining-room volumio[1139]: error: MyVolumio Custom Token format not valid, refreshing it Mar 25 16:57:11 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 25 16:57:11 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 16:57:11 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 25 16:57:12 dining-room volumio-remote-updater[714]: Test mode disabled Mar 25 16:57:12 dining-room volumio-remote-updater[714]: Alpha mode disabled Mar 25 16:57:12 dining-room volumio-remote-updater[714]: Alpha legacy test mode disabled Mar 25 16:57:12 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Mar 25 16:57:12 dining-room volumio[1139]: info: MyVolumio login type: Token Mar 25 16:57:12 dining-room volumio[1139]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Mar 25 16:57:12 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Mar 25 16:57:13 dining-room volumio[1139]: info: Getting Spotify volume Mar 25 16:57:13 dining-room volumio[1139]: info: Spotify volume: 100 Mar 25 16:57:13 dining-room volumio[1139]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Mar 25 16:57:13 dining-room volumio[1139]: info: CoreCommandRouter::volumioGetState Mar 25 16:57:13 dining-room volumio[1139]: info: CorePlayQueue::getTrack 0 Mar 25 16:57:14 dining-room volumio[1139]: SPOTIFY: RECEIVED VOLUMIO VOLUME 24 Mar 25 16:57:14 dining-room volumio[1139]: SPOTIFY: SPOTIFY VOLUME 100 Mar 25 16:57:14 dining-room volumio[1139]: SPOTIFY: VOLUMIO VOLUME 24 Mar 25 16:57:14 dining-room volumio[1139]: SPOTIFY: DELTA VOLUME ENOUGH: true Mar 25 16:57:14 dining-room volumio[1139]: info: Setting Spotify Volume from Volumio: 24 Mar 25 16:57:14 dining-room volumio[1139]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Mar 25 16:57:15 dining-room volumio[1139]: info: MyVolumio token set successfully Mar 25 16:57:15 dining-room volumio[1139]: info: MYVOLUMIO: Adding device Mar 25 16:57:15 dining-room volumio[1139]: info: MYVOLUMIO: Evaluating Server Mar 25 16:57:16 dining-room volumio[1139]: SPOTIFY: SETTING SPOTIFY VOLUME 24 Mar 25 16:57:16 dining-room volumio[1139]: info: Sending Spotify command with payload to local API: /player/volume Mar 25 16:57:16 dining-room volumio[1139]: info: MyVolumio status changed Mar 25 16:57:16 dining-room volumio[1139]: info: Streaming services startup Mar 25 16:57:16 dining-room volumio[1139]: info: Starting Streaming Daemon Mar 25 16:57:16 dining-room volumio[1139]: info: Removing browser output: myVolumio user plan is not superstar Mar 25 16:57:16 dining-room volumio[1139]: info: Removing audio output: Mar 25 16:57:16 dining-room volumio[1139]: info: Stoppping Tunnel 1 Mar 25 16:57:16 dining-room sudo[1767]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Mar 25 16:57:16 dining-room sudo[1767]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 16:57:16 dining-room sudo[1769]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Mar 25 16:57:16 dining-room sudo[1767]: pam_unix(sudo:session): session closed for user root Mar 25 16:57:16 dining-room sudo[1769]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 16:57:16 dining-room go-librespot[1591]: time="2026-03-25T16:57:16+13:00" level=debug msg="update volume requested to 15728/65535" Mar 25 16:57:16 dining-room 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. Mar 25 16:57:16 dining-room 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. Mar 25 16:57:16 dining-room 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. Mar 25 16:57:16 dining-room 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. Mar 25 16:57:16 dining-room 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. Mar 25 16:57:16 dining-room 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. Mar 25 16:57:16 dining-room 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. Mar 25 16:57:16 dining-room 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. Mar 25 16:57:16 dining-room sudo[1769]: pam_unix(sudo:session): session closed for user root Mar 25 16:57:16 dining-room volumio[1139]: info: Setting Geolocation for MyVolumio to au1 Mar 25 16:57:16 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 16:57:16 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 16:57:16 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 16:57:16 dining-room volumio[1139]: error: Cannot start Volumio Streaming Daemon Mar 25 16:57:16 dining-room volumio[1139]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Mar 25 16:57:16 dining-room volumio[1139]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Mar 25 16:57:16 dining-room volumio[1139]: info: Remote SSH Stopped Mar 25 16:57:16 dining-room go-librespot[1591]: time="2026-03-25T16:57:16+13:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 25 16:57:16 dining-room go-librespot[1591]: time="2026-03-25T16:57:16+13:00" level=trace msg="emitting websocket event: volume" Mar 25 16:57:16 dining-room volumio[1139]: SPOTIFY: received: {"type":"volume","data":{"value":24,"max":100}} Mar 25 16:57:16 dining-room volumio[1139]: SPOTIFY: RECEIVED SPOTIFY VOLUME 24 Mar 25 16:57:17 dining-room volumio[1139]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Mar 25 16:57:17 dining-room volumio[1139]: info: Updating MyVolumio device info Mar 25 16:57:17 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 16:57:17 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 16:57:17 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 16:57:18 dining-room volumio[1139]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Mar 25 16:57:19 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 25 16:57:19 dining-room volumio[1139]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Mar 25 16:57:19 dining-room volumio[1139]: info: CoreCommandRouter::volumioGetState Mar 25 16:57:19 dining-room volumio[1139]: info: CorePlayQueue::getTrack 0 Mar 25 16:57:21 dining-room go-librespot[1591]: time="2026-03-25T16:57:21+13:00" level=trace msg="sent dealer ping" Mar 25 16:57:21 dining-room volumio[1139]: info: MYVOLUMIO: Adding device Mar 25 16:57:21 dining-room volumio[1139]: info: MYVOLUMIO: Evaluating Server Mar 25 16:57:21 dining-room go-librespot[1591]: time="2026-03-25T16:57:21+13:00" level=trace msg="received dealer pong" Mar 25 16:57:22 dining-room volumio[1139]: info: Setting Geolocation for MyVolumio to au1 Mar 25 16:57:22 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 16:57:22 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 16:57:22 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 16:57:23 dining-room volumio[1139]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Mar 25 16:57:23 dining-room volumio[1139]: info: Updating MyVolumio device info Mar 25 16:57:23 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 16:57:23 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 16:57:23 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 16:57:24 dining-room volumio[1139]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Mar 25 16:57:24 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 16:57:24 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 16:57:24 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Mar 25 16:57:24 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Mar 25 16:57:24 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Mar 25 16:57:24 dining-room volumio[1139]: info: CoreCommandRouter::volumioGetBrowseSources Mar 25 16:57:24 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 25 16:57:29 dining-room volumio[1139]: error: MyVolumio Plugin failed to authenticate in a timely fashion Mar 25 16:57:29 dining-room volumio[1139]: info: Completed starting MyVolumio Plugin Mar 25 16:57:29 dining-room volumio[1139]: [Metrics] CommandRouter: 75s 41.67ms Mar 25 16:57:29 dining-room volumio[1139]: info: CoreCommandRouter::volumiosetStartupVolume Mar 25 16:57:29 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 16:57:29 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 25 16:57:29 dining-room volumio[1139]: info: CoreCommandRouter::Close All Modals sent Mar 25 16:57:29 dining-room volumio[1139]: info: CoreCommandRouter::Close All Modals sent Mar 25 16:57:29 dining-room volumio[1139]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Mar 25 16:57:29 dining-room volumio[1139]: info: FusionDsp - ---- read samplerate from file: 44100 Mar 25 16:57:29 dining-room volumio[1139]: info: camilladsp stopping service pid 1560... Mar 25 16:57:29 dining-room volumio[1139]: info: camilladsp service terminated, instance 1 Mar 25 16:57:29 dining-room volumio[1139]: info: FusionDsp - If filter freq >samplerate/2 then disable it Mar 25 16:57:29 dining-room volumio[1139]: info: camilladsp service started and running in background, instance 1 Mar 25 16:57:30 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Mar 25 16:57:30 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Mar 25 16:57:30 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Mar 25 16:57:36 dining-room volumio[1139]: info: BOOT COMPLETED Mar 25 16:57:42 dining-room go-librespot[1591]: time="2026-03-25T16:57:42+13:00" level=debug msg="handling transfer player command from 5a98a9e31dcb8265d0a95b5aa480a312faf5ed0b" Mar 25 16:57:42 dining-room go-librespot[1591]: time="2026-03-25T16:57:42+13:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1EIeQvoRLAWmfq" Mar 25 16:57:42 dining-room go-librespot[1591]: time="2026-03-25T16:57:42+13:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1EIeQvoRLAWmfq" Mar 25 16:57:42 dining-room go-librespot[1591]: time="2026-03-25T16:57:42+13:00" level=debug msg="loading track (paused: false, position: 21024ms)" uri="spotify:track:2VW6HO7fSA4dkbGgG1xkdn" Mar 25 16:57:42 dining-room go-librespot[1591]: time="2026-03-25T16:57:42+13:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 25 16:57:42 dining-room go-librespot[1591]: time="2026-03-25T16:57:42+13:00" level=trace msg="emitting websocket event: will_play" Mar 25 16:57:42 dining-room volumio[1139]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1EIeQvoRLAWmfq","uri":"spotify:track:2VW6HO7fSA4dkbGgG1xkdn","play_origin":"playlist"}} Mar 25 16:57:42 dining-room go-librespot[1591]: time="2026-03-25T16:57:42+13:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 415" Mar 25 16:57:42 dining-room go-librespot[1591]: time="2026-03-25T16:57:42+13:00" level=debug msg="selected format OGG_VORBIS_320 (a22efa74b2e1b453a7b8472f4220c65bd6b88087)" uri="spotify:track:2VW6HO7fSA4dkbGgG1xkdn" Mar 25 16:57:42 dining-room go-librespot[1591]: time="2026-03-25T16:57:42+13:00" level=debug msg="requested aes key for file a22efa74b2e1b453a7b8472f4220c65bd6b88087, gid: 2VW6HO7fSA4dkbGgG1xkdn" Mar 25 16:57:42 dining-room go-librespot[1591]: time="2026-03-25T16:57:42+13:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1686" Mar 25 16:57:43 dining-room go-librespot[1591]: time="2026-03-25T16:57:43+13:00" level=trace msg="found 2 cdn urls" uri="spotify:track:2VW6HO7fSA4dkbGgG1xkdn" Mar 25 16:57:43 dining-room go-librespot[1591]: time="2026-03-25T16:57:43+13:00" level=debug msg="fetched first chunk of 14, total size is 7307068 bytes" uri="spotify:track:2VW6HO7fSA4dkbGgG1xkdn" Mar 25 16:57:44 dining-room go-librespot[1591]: time="2026-03-25T16:57:44+13:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1300" Mar 25 16:57:44 dining-room go-librespot[1591]: time="2026-03-25T16:57:44+13:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:2VW6HO7fSA4dkbGgG1xkdn" Mar 25 16:57:44 dining-room go-librespot[1591]: time="2026-03-25T16:57:44+13:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:2VW6HO7fSA4dkbGgG1xkdn" Mar 25 16:57:44 dining-room go-librespot[1591]: time="2026-03-25T16:57:44+13:00" level=debug msg="fetched chunk 4/13, size: 524288" uri="spotify:track:2VW6HO7fSA4dkbGgG1xkdn" Mar 25 16:57:44 dining-room go-librespot[1591]: time="2026-03-25T16:57:44+13:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:2VW6HO7fSA4dkbGgG1xkdn" Mar 25 16:57:44 dining-room go-librespot[1591]: time="2026-03-25T16:57:44+13:00" level=trace msg="seek to 21024ms (diff: 143ms, samples: 927158, bytes: 806657)" uri="spotify:track:2VW6HO7fSA4dkbGgG1xkdn" Mar 25 16:57:44 dining-room go-librespot[1591]: time="2026-03-25T16:57:44+13:00" level=debug msg="created new output device" Mar 25 16:57:44 dining-room go-librespot[1591]: time="2026-03-25T16:57:44+13:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Mar 25 16:57:44 dining-room go-librespot[1591]: time="2026-03-25T16:57:44+13:00" level=info msg="loaded track \"The Theme\" (paused: false, position: 21024ms, duration: 187343ms, prefetched: false)" uri="spotify:track:2VW6HO7fSA4dkbGgG1xkdn" Mar 25 16:57:44 dining-room volumio[1139]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Mar 25 16:57:44 dining-room volumio[1139]: info: FusionDsp - ---- read samplerate from file: 44100 Mar 25 16:57:44 dining-room volumio[1139]: info: FusionDsp - If filter freq >samplerate/2 then disable it Mar 25 16:57:44 dining-room go-librespot[1591]: time="2026-03-25T16:57:44+13:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 25 16:57:44 dining-room go-librespot[1591]: time="2026-03-25T16:57:44+13:00" level=trace msg="scheduling prefetch in 136s" Mar 25 16:57:44 dining-room go-librespot[1591]: time="2026-03-25T16:57:44+13:00" level=trace msg="emitting websocket event: metadata" Mar 25 16:57:44 dining-room go-librespot[1591]: time="2026-03-25T16:57:44+13:00" level=trace msg="emitting websocket event: active" Mar 25 16:57:44 dining-room go-librespot[1591]: time="2026-03-25T16:57:44+13:00" level=debug msg="sending successful reply for dealer request" Mar 25 16:57:44 dining-room go-librespot[1591]: time="2026-03-25T16:57:44+13:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 25 16:57:44 dining-room go-librespot[1591]: time="2026-03-25T16:57:44+13:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 25 16:57:44 dining-room go-librespot[1591]: time="2026-03-25T16:57:44+13:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 25 16:57:44 dining-room volumio[1139]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2VW6HO7fSA4dkbGgG1xkdn","name":"The Theme","artist_names":["Jurgen Vries"],"album_name":"The Theme","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02fde4de20caf1ad63591d8640","position":21024,"duration":187343,"release_date":"year:2002 month:9 day:2","track_number":1,"disc_number":1}} Mar 25 16:57:44 dining-room volumio[1139]: SPOTIFY: received: {"type":"active","data":null} Mar 25 16:57:44 dining-room volumio[1139]: info: Aligning Spotify Volume to Volumio Volume Mar 25 16:57:44 dining-room volumio[1139]: info: CoreCommandRouter::volumioGetState Mar 25 16:57:44 dining-room volumio[1139]: info: CorePlayQueue::getTrack 0 Mar 25 16:57:44 dining-room volumio[1139]: info: Setting Spotify Volume from Volumio: 24 Mar 25 16:57:45 dining-room go-librespot[1591]: time="2026-03-25T16:57:45+13:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 25 16:57:45 dining-room go-librespot[1591]: time="2026-03-25T16:57:45+13:00" level=trace msg="emitting websocket event: playing" Mar 25 16:57:45 dining-room volumio[1139]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:37i9dQZF1EIeQvoRLAWmfq","uri":"spotify:track:2VW6HO7fSA4dkbGgG1xkdn","resume":false,"play_origin":"playlist"}} Mar 25 16:57:45 dining-room volumio[1139]: info: Spotify is playing in volatile mode Mar 25 16:57:45 dining-room volumio[1139]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 25 16:57:45 dining-room volumio[1139]: SPOTIFY: UNSET VOLATILE Mar 25 16:57:45 dining-room volumio[1139]: SPOTIFY: {"status":"stop","position":0,"title":"Utopia (New Ears Mix)","artist":"Goldfrapp","album":"Café Del Mar - Volumen Ocho","albumart":"/albumart?cacheid=44&web=Goldfrapp/Caf%C3%A9%20Del%20Mar%20-%20Volumen%20Ocho/extralarge&path=%2FUSB%2FHANS_BLADE%2FCompilations%2FCaf%C3%A9%20Del%20Mar%20-%20Volumen%20Ocho&metadata=false","uri":"mnt/USB/HANS_BLADE/Compilations/Café Del Mar - Volumen Ocho/01 Utopia (New Ears Mix).m4a","trackType":"m4a","seek":0,"duration":190,"random":false,"repeat":null,"repeatSingle":false,"consume":false,"volume":24,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"m4a","updatedb":false,"volatile":false,"service":"mpd"} Mar 25 16:57:45 dining-room volumio[1139]: SPOTIFY: PUSH STATE SPOTIFY Mar 25 16:57:45 dining-room volumio[1139]: SPOTIFY: {"status":"play","service":"spop","title":"The Theme","artist":"Jurgen Vries","album":"The Theme","albumart":"https://i.scdn.co/image/ab67616d00001e02fde4de20caf1ad63591d8640","uri":"spotify:track:2VW6HO7fSA4dkbGgG1xkdn","trackType":"spotify","seek":21024,"duration":187,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 25 16:57:45 dining-room volumio[1139]: info: CoreCommandRouter::servicePushState Mar 25 16:57:45 dining-room volumio[1139]: info: CoreStateMachine::pushState Mar 25 16:57:45 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 25 16:57:45 dining-room volumio[1139]: info: CoreCommandRouter::volumioPushState Mar 25 16:57:45 dining-room volumio[1139]: SPOTIFY: RECEIVED VOLUMIO VOLUME 24 Mar 25 16:57:45 dining-room volumio[1139]: SPOTIFY: PUSH STATE SPOTIFY Mar 25 16:57:45 dining-room volumio[1139]: SPOTIFY: {"status":"play","service":"spop","title":"The Theme","artist":"Jurgen Vries","album":"The Theme","albumart":"https://i.scdn.co/image/ab67616d00001e02fde4de20caf1ad63591d8640","uri":"spotify:track:2VW6HO7fSA4dkbGgG1xkdn","trackType":"spotify","seek":21024,"duration":187,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 25 16:57:45 dining-room volumio[1139]: info: CoreCommandRouter::servicePushState Mar 25 16:57:45 dining-room volumio[1139]: info: CoreStateMachine::pushState Mar 25 16:57:45 dining-room volumio[1139]: info: CoreCommandRouter::volumioPushState Mar 25 16:57:45 dining-room volumio[1139]: SPOTIFY: RECEIVED VOLUMIO VOLUME 24 Mar 25 16:57:46 dining-room volumio[1139]: SPOTIFY: SETTING SPOTIFY VOLUME 24 Mar 25 16:57:46 dining-room volumio[1139]: info: Sending Spotify command with payload to local API: /player/volume Mar 25 16:57:46 dining-room go-librespot[1591]: time="2026-03-25T16:57:46+13:00" level=debug msg="update volume requested to 15728/65535" Mar 25 16:57:46 dining-room go-librespot[1591]: time="2026-03-25T16:57:46+13:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 25 16:57:46 dining-room go-librespot[1591]: time="2026-03-25T16:57:46+13:00" level=trace msg="emitting websocket event: volume" Mar 25 16:57:46 dining-room volumio[1139]: SPOTIFY: received: {"type":"volume","data":{"value":24,"max":100}} Mar 25 16:57:46 dining-room volumio[1139]: SPOTIFY: RECEIVED SPOTIFY VOLUME 24 Mar 25 16:57:47 dining-room go-librespot[1591]: time="2026-03-25T16:57:47+13:00" level=debug msg="handling play player command from 5a98a9e31dcb8265d0a95b5aa480a312faf5ed0b" Mar 25 16:57:47 dining-room go-librespot[1591]: time="2026-03-25T16:57:47+13:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1EIeQvoRLAWmfq" Mar 25 16:57:47 dining-room go-librespot[1591]: time="2026-03-25T16:57:47+13:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1EIeQvoRLAWmfq" Mar 25 16:57:47 dining-room go-librespot[1591]: time="2026-03-25T16:57:47+13:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:1FmBkR0DLsvas4rLy8x0JV" Mar 25 16:57:47 dining-room go-librespot[1591]: time="2026-03-25T16:57:47+13:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 25 16:57:47 dining-room go-librespot[1591]: time="2026-03-25T16:57:47+13:00" level=trace msg="emitting websocket event: will_play" Mar 25 16:57:47 dining-room volumio[1139]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1EIeQvoRLAWmfq","uri":"spotify:track:1FmBkR0DLsvas4rLy8x0JV","play_origin":"playlist"}} Mar 25 16:57:48 dining-room go-librespot[1591]: time="2026-03-25T16:57:48+13:00" level=debug msg="selected format OGG_VORBIS_320 (70da9acef07902fa26ee6b7b96d800b19d1bb2d6)" uri="spotify:track:1FmBkR0DLsvas4rLy8x0JV" Mar 25 16:57:48 dining-room go-librespot[1591]: time="2026-03-25T16:57:48+13:00" level=debug msg="requested aes key for file 70da9acef07902fa26ee6b7b96d800b19d1bb2d6, gid: 1FmBkR0DLsvas4rLy8x0JV" Mar 25 16:57:48 dining-room go-librespot[1591]: time="2026-03-25T16:57:48+13:00" level=trace msg="found 2 cdn urls" uri="spotify:track:1FmBkR0DLsvas4rLy8x0JV" Mar 25 16:57:48 dining-room go-librespot[1591]: time="2026-03-25T16:57:48+13:00" level=debug msg="fetched first chunk of 16, total size is 8096404 bytes" uri="spotify:track:1FmBkR0DLsvas4rLy8x0JV" Mar 25 16:57:48 dining-room go-librespot[1591]: time="2026-03-25T16:57:48+13:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:1FmBkR0DLsvas4rLy8x0JV" Mar 25 16:57:48 dining-room go-librespot[1591]: time="2026-03-25T16:57:48+13:00" level=info msg="loaded track \"Warrior\" (paused: false, position: 1ms, duration: 227428ms, prefetched: false)" uri="spotify:track:1FmBkR0DLsvas4rLy8x0JV" Mar 25 16:57:49 dining-room go-librespot[1591]: time="2026-03-25T16:57:49+13:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:1FmBkR0DLsvas4rLy8x0JV" Mar 25 16:57:49 dining-room go-librespot[1591]: time="2026-03-25T16:57:49+13:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 25 16:57:49 dining-room go-librespot[1591]: time="2026-03-25T16:57:49+13:00" level=trace msg="scheduling prefetch in 197s" Mar 25 16:57:49 dining-room go-librespot[1591]: time="2026-03-25T16:57:49+13:00" level=trace msg="emitting websocket event: metadata" Mar 25 16:57:49 dining-room go-librespot[1591]: time="2026-03-25T16:57:49+13:00" level=debug msg="sending successful reply for dealer request" Mar 25 16:57:49 dining-room volumio[1139]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1FmBkR0DLsvas4rLy8x0JV","name":"Warrior","artist_names":["Warrior"],"album_name":"Warrior (Remixes)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02ed8f19355b22a421ac2900c5","position":1,"duration":227428,"release_date":"year:2000 month:8 day:5","track_number":8,"disc_number":1}} Mar 25 16:57:49 dining-room go-librespot[1591]: time="2026-03-25T16:57:49+13:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:1FmBkR0DLsvas4rLy8x0JV" Mar 25 16:57:49 dining-room go-librespot[1591]: time="2026-03-25T16:57:49+13:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:1FmBkR0DLsvas4rLy8x0JV" Mar 25 16:57:49 dining-room go-librespot[1591]: time="2026-03-25T16:57:49+13:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 25 16:57:49 dining-room go-librespot[1591]: time="2026-03-25T16:57:49+13:00" level=trace msg="emitting websocket event: playing" Mar 25 16:57:49 dining-room volumio[1139]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:37i9dQZF1EIeQvoRLAWmfq","uri":"spotify:track:1FmBkR0DLsvas4rLy8x0JV","resume":false,"play_origin":"playlist"}} Mar 25 16:57:49 dining-room volumio[1139]: SPOTIFY: PUSH STATE SPOTIFY Mar 25 16:57:49 dining-room volumio[1139]: SPOTIFY: {"status":"play","service":"spop","title":"Warrior","artist":"Warrior","album":"Warrior (Remixes)","albumart":"https://i.scdn.co/image/ab67616d00001e02ed8f19355b22a421ac2900c5","uri":"spotify:track:1FmBkR0DLsvas4rLy8x0JV","trackType":"spotify","seek":1,"duration":227,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 25 16:57:49 dining-room volumio[1139]: info: CoreCommandRouter::servicePushState Mar 25 16:57:49 dining-room volumio[1139]: info: CoreStateMachine::pushState Mar 25 16:57:49 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 25 16:57:49 dining-room volumio[1139]: info: CoreCommandRouter::volumioPushState Mar 25 16:57:49 dining-room volumio[1139]: SPOTIFY: RECEIVED VOLUMIO VOLUME 24 Mar 25 16:57:49 dining-room volumio[1139]: SPOTIFY: PUSH STATE SPOTIFY Mar 25 16:57:49 dining-room volumio[1139]: SPOTIFY: {"status":"play","service":"spop","title":"Warrior","artist":"Warrior","album":"Warrior (Remixes)","albumart":"https://i.scdn.co/image/ab67616d00001e02ed8f19355b22a421ac2900c5","uri":"spotify:track:1FmBkR0DLsvas4rLy8x0JV","trackType":"spotify","seek":1,"duration":227,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 25 16:57:49 dining-room volumio[1139]: info: CoreCommandRouter::servicePushState Mar 25 16:57:49 dining-room volumio[1139]: info: CoreStateMachine::pushState Mar 25 16:57:49 dining-room volumio[1139]: info: CoreCommandRouter::volumioPushState Mar 25 16:57:49 dining-room volumio[1139]: SPOTIFY: RECEIVED VOLUMIO VOLUME 24 Mar 25 16:57:51 dining-room go-librespot[1591]: time="2026-03-25T16:57:51+13:00" level=trace msg="sent dealer ping" Mar 25 16:57:51 dining-room go-librespot[1591]: time="2026-03-25T16:57:51+13:00" level=trace msg="received dealer pong" Mar 25 16:57:52 dining-room go-librespot[1591]: time="2026-03-25T16:57:52+13:00" level=debug msg="handling play player command from 5a98a9e31dcb8265d0a95b5aa480a312faf5ed0b" Mar 25 16:57:52 dining-room go-librespot[1591]: time="2026-03-25T16:57:52+13:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1EIeQvoRLAWmfq" Mar 25 16:57:52 dining-room go-librespot[1591]: time="2026-03-25T16:57:52+13:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1EIeQvoRLAWmfq" Mar 25 16:57:52 dining-room go-librespot[1591]: time="2026-03-25T16:57:52+13:00" level=debug msg="loading track (paused: false, position: 3ms)" uri="spotify:track:6ehxerrPHbALa2XzegE9AF" Mar 25 16:57:53 dining-room go-librespot[1591]: time="2026-03-25T16:57:53+13:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 25 16:57:53 dining-room go-librespot[1591]: time="2026-03-25T16:57:53+13:00" level=trace msg="emitting websocket event: will_play" Mar 25 16:57:53 dining-room volumio[1139]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1EIeQvoRLAWmfq","uri":"spotify:track:6ehxerrPHbALa2XzegE9AF","play_origin":"playlist"}} Mar 25 16:57:53 dining-room go-librespot[1591]: time="2026-03-25T16:57:53+13:00" level=debug msg="selected format OGG_VORBIS_320 (4c6f8498ff26e87a4c24f1d9fba1d6f4213f7dc6)" uri="spotify:track:6ehxerrPHbALa2XzegE9AF" Mar 25 16:57:53 dining-room go-librespot[1591]: time="2026-03-25T16:57:53+13:00" level=debug msg="requested aes key for file 4c6f8498ff26e87a4c24f1d9fba1d6f4213f7dc6, gid: 6ehxerrPHbALa2XzegE9AF" Mar 25 16:57:53 dining-room go-librespot[1591]: time="2026-03-25T16:57:53+13:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6ehxerrPHbALa2XzegE9AF" Mar 25 16:57:54 dining-room go-librespot[1591]: time="2026-03-25T16:57:54+13:00" level=debug msg="fetched first chunk of 30, total size is 15508547 bytes" uri="spotify:track:6ehxerrPHbALa2XzegE9AF" Mar 25 16:57:54 dining-room go-librespot[1591]: time="2026-03-25T16:57:54+13:00" level=trace msg="seek to 3ms (diff: -102ms, samples: 132, bytes: 4346)" uri="spotify:track:6ehxerrPHbALa2XzegE9AF" Mar 25 16:57:54 dining-room go-librespot[1591]: time="2026-03-25T16:57:54+13:00" level=info msg="loaded track \"Coming Home - Transa Remix\" (paused: false, position: 3ms, duration: 464826ms, prefetched: false)" uri="spotify:track:6ehxerrPHbALa2XzegE9AF" Mar 25 16:57:54 dining-room go-librespot[1591]: time="2026-03-25T16:57:54+13:00" level=debug msg="fetched chunk 1/29, size: 524288" uri="spotify:track:6ehxerrPHbALa2XzegE9AF" Mar 25 16:57:54 dining-room go-librespot[1591]: time="2026-03-25T16:57:54+13:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 25 16:57:54 dining-room go-librespot[1591]: time="2026-03-25T16:57:54+13:00" level=trace msg="scheduling prefetch in 434s" Mar 25 16:57:54 dining-room go-librespot[1591]: time="2026-03-25T16:57:54+13:00" level=trace msg="emitting websocket event: metadata" Mar 25 16:57:54 dining-room go-librespot[1591]: time="2026-03-25T16:57:54+13:00" level=debug msg="sending successful reply for dealer request" Mar 25 16:57:54 dining-room volumio[1139]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6ehxerrPHbALa2XzegE9AF","name":"Coming Home - Transa Remix","artist_names":["Blue Amazon","Vicky Webb","Transa"],"album_name":"Coming Home","album_cover_url":"https://i.scdn.co/image/ab67616d00001e024b0af1721d59f4a9e15f0444","position":3,"duration":464826,"release_date":"year:1999","track_number":1,"disc_number":1}} Mar 25 16:57:54 dining-room go-librespot[1591]: time="2026-03-25T16:57:54+13:00" level=debug msg="fetched chunk 3/29, size: 524288" uri="spotify:track:6ehxerrPHbALa2XzegE9AF" Mar 25 16:57:54 dining-room go-librespot[1591]: time="2026-03-25T16:57:54+13:00" level=debug msg="fetched chunk 2/29, size: 524288" uri="spotify:track:6ehxerrPHbALa2XzegE9AF" Mar 25 16:57:54 dining-room go-librespot[1591]: time="2026-03-25T16:57:54+13:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 25 16:57:54 dining-room go-librespot[1591]: time="2026-03-25T16:57:54+13:00" level=trace msg="emitting websocket event: playing" Mar 25 16:57:54 dining-room volumio[1139]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:37i9dQZF1EIeQvoRLAWmfq","uri":"spotify:track:6ehxerrPHbALa2XzegE9AF","resume":false,"play_origin":"playlist"}} Mar 25 16:57:54 dining-room volumio[1139]: SPOTIFY: PUSH STATE SPOTIFY Mar 25 16:57:54 dining-room volumio[1139]: SPOTIFY: {"status":"play","service":"spop","title":"Coming Home - Transa Remix","artist":"Blue Amazon, Vicky Webb, Transa","album":"Coming Home","albumart":"https://i.scdn.co/image/ab67616d00001e024b0af1721d59f4a9e15f0444","uri":"spotify:track:6ehxerrPHbALa2XzegE9AF","trackType":"spotify","seek":3,"duration":464,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 25 16:57:54 dining-room volumio[1139]: info: CoreCommandRouter::servicePushState Mar 25 16:57:54 dining-room volumio[1139]: info: CoreStateMachine::pushState Mar 25 16:57:54 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 25 16:57:54 dining-room volumio[1139]: info: CoreCommandRouter::volumioPushState Mar 25 16:57:54 dining-room volumio[1139]: SPOTIFY: RECEIVED VOLUMIO VOLUME 24 Mar 25 16:57:54 dining-room volumio[1139]: SPOTIFY: PUSH STATE SPOTIFY Mar 25 16:57:54 dining-room volumio[1139]: SPOTIFY: {"status":"play","service":"spop","title":"Coming Home - Transa Remix","artist":"Blue Amazon, Vicky Webb, Transa","album":"Coming Home","albumart":"https://i.scdn.co/image/ab67616d00001e024b0af1721d59f4a9e15f0444","uri":"spotify:track:6ehxerrPHbALa2XzegE9AF","trackType":"spotify","seek":3,"duration":464,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 25 16:57:54 dining-room volumio[1139]: info: CoreCommandRouter::servicePushState Mar 25 16:57:54 dining-room volumio[1139]: info: CoreStateMachine::pushState Mar 25 16:57:54 dining-room volumio[1139]: info: CoreCommandRouter::volumioPushState Mar 25 16:57:54 dining-room volumio[1139]: SPOTIFY: RECEIVED VOLUMIO VOLUME 24 Mar 25 16:58:05 dining-room go-librespot[1591]: time="2026-03-25T16:58:05+13:00" level=debug msg="handling pause player command from 5a98a9e31dcb8265d0a95b5aa480a312faf5ed0b" Mar 25 16:58:05 dining-room go-librespot[1591]: time="2026-03-25T16:58:05+13:00" level=debug msg="pause track at 11852ms" Mar 25 16:58:06 dining-room go-librespot[1591]: time="2026-03-25T16:58:06+13:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 25 16:58:06 dining-room go-librespot[1591]: time="2026-03-25T16:58:06+13:00" level=debug msg="sending successful reply for dealer request" Mar 25 16:58:06 dining-room go-librespot[1591]: time="2026-03-25T16:58:06+13:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 25 16:58:06 dining-room go-librespot[1591]: time="2026-03-25T16:58:06+13:00" level=trace msg="emitting websocket event: paused" Mar 25 16:58:06 dining-room volumio[1139]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:playlist:37i9dQZF1EIeQvoRLAWmfq","uri":"spotify:track:6ehxerrPHbALa2XzegE9AF","play_origin":"playlist"}} Mar 25 16:58:06 dining-room volumio[1139]: SPOTIFY: PUSH STATE SPOTIFY Mar 25 16:58:06 dining-room volumio[1139]: SPOTIFY: {"status":"pause","service":"spop","title":"Coming Home - Transa Remix","artist":"Blue Amazon, Vicky Webb, Transa","album":"Coming Home","albumart":"https://i.scdn.co/image/ab67616d00001e024b0af1721d59f4a9e15f0444","uri":"spotify:track:6ehxerrPHbALa2XzegE9AF","trackType":"spotify","seek":12003,"duration":464,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 25 16:58:06 dining-room volumio[1139]: info: CoreCommandRouter::servicePushState Mar 25 16:58:06 dining-room volumio[1139]: info: CoreStateMachine::pushState Mar 25 16:58:06 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 25 16:58:06 dining-room volumio[1139]: info: CoreCommandRouter::volumioPushState Mar 25 16:58:06 dining-room volumio[1139]: SPOTIFY: RECEIVED VOLUMIO VOLUME 24 Mar 25 16:58:20 dining-room sudo[1927]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 25 16:58:20 dining-room sudo[1927]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 16:58:20 dining-room sudo[1929]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 25 16:58:20 dining-room sudo[1929]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 16:58:20 dining-room sudo[1927]: pam_unix(sudo:session): session closed for user root Mar 25 16:58:20 dining-room sudo[1929]: pam_unix(sudo:session): session closed for user root Mar 25 16:58:20 dining-room volumio[1139]: verbose: New Socket.io Connection to 192.168.0.105 from 192.168.0.107 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/146.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Mar 25 16:58:21 dining-room sudo[1937]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 25 16:58:21 dining-room sudo[1937]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 16:58:21 dining-room sudo[1939]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 25 16:58:21 dining-room sudo[1939]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 16:58:21 dining-room sudo[1937]: pam_unix(sudo:session): session closed for user root Mar 25 16:58:21 dining-room go-librespot[1591]: time="2026-03-25T16:58:21+13:00" level=trace msg="sent dealer ping" Mar 25 16:58:21 dining-room sudo[1939]: pam_unix(sudo:session): session closed for user root Mar 25 16:58:21 dining-room volumio[1139]: verbose: New Socket.io Connection to 192.168.0.105 from 192.168.0.107 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/146.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Mar 25 16:58:21 dining-room go-librespot[1591]: time="2026-03-25T16:58:21+13:00" level=trace msg="received dealer pong" Mar 25 16:58:21 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 25 16:58:22 dining-room volumio[1139]: info: CoreCommandRouter::volumioGetVisibleSources Mar 25 16:58:22 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 25 16:58:22 dining-room volumio[1139]: info: CoreCommandRouter::volumioGetState Mar 25 16:58:22 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 25 16:58:22 dining-room volumio[1139]: info: CoreCommandRouter::volumioGetQueue Mar 25 16:58:22 dining-room volumio[1139]: info: CoreStateMachine::getQueue Mar 25 16:58:22 dining-room volumio[1139]: info: CorePlayQueue::getQueue Mar 25 16:58:22 dining-room volumio[1139]: info: Listing playlists Mar 25 16:58:22 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 25 16:58:22 dining-room volumio[1139]: info: Received Get System Info Mar 25 16:58:22 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 25 16:58:22 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 25 16:58:22 dining-room volumio[1139]: info: Discovery: Getting this device information Mar 25 16:58:22 dining-room volumio[1139]: info: CoreCommandRouter::volumioGetState Mar 25 16:58:22 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 25 16:58:22 dining-room volumio[1139]: info: CoreCommandRouter::volumioGetState Mar 25 16:58:22 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 25 16:58:22 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 25 16:58:22 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 25 16:58:22 dining-room volumio[1139]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 25 16:58:24 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 25 16:58:24 dining-room volumio[1139]: info: Received Get System Info Mar 25 16:58:24 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 25 16:58:24 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 25 16:58:24 dining-room volumio[1139]: info: Discovery: Getting this device information Mar 25 16:58:24 dining-room volumio[1139]: info: CoreCommandRouter::volumioGetState Mar 25 16:58:24 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 25 16:58:24 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Mar 25 16:58:25 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 25 16:58:25 dining-room volumio[1139]: info: Received Get System Info Mar 25 16:58:25 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 25 16:58:25 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 25 16:58:25 dining-room volumio[1139]: info: Discovery: Getting this device information Mar 25 16:58:25 dining-room volumio[1139]: info: CoreCommandRouter::volumioGetState Mar 25 16:58:25 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 25 16:58:25 dining-room volumio[1139]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Mar 25 16:58:25 dining-room volumio[1139]: info: In handleBrowseUri, curUri=spotify:user:spotify:playlist:39N8J7qHXGtCcwjQYy1UhZ Mar 25 16:58:27 dining-room volumio[1139]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 25 16:58:27 dining-room volumio[1139]: TypeError: Cannot read properties of null (reading '0') Mar 25 16:58:27 dining-room volumio[1139]: at /data/plugins/music_service/spop/index.js:2507:56 Mar 25 16:58:27 dining-room volumio[1139]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Mar 25 16:58:27 dining-room volumio[1139]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 25 16:58:33 dining-room sudo[1988]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-25 16:57' Mar 25 16:58:33 dining-room sudo[1988]: 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="dc61260dec5515dafd2b634881860b4c46c919ff" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Mar 6 16:46:58 UTC 2026" VOLUMIO_VERSION="4.103" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="aa741395b8bfc648ff5d04e312f53d2c"