Feb 08 10:09:31 volumio ntpd[1272]: CLOCK: time stepped by 129327.804366 Feb 08 10:09:31 volumio ntpd[1272]: CLOCK: time changed from 2026-02-06 to 2026-02-08 Feb 08 10:09:31 volumio ntpd[1272]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Feb 08 10:09:33 volumio volumio[1477]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Feb 08 10:09:33 volumio volumio[1477]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 08 10:09:33 volumio volumio[1477]: info: Received Get System Info Feb 08 10:09:33 volumio volumio[1477]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 08 10:09:33 volumio volumio[1477]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 08 10:09:33 volumio volumio[1477]: info: Discovery: Getting this device information Feb 08 10:09:33 volumio volumio[1477]: info: CoreCommandRouter::volumioGetState Feb 08 10:09:33 volumio volumio[1477]: info: CorePlayQueue::getTrack 0 Feb 08 10:09:33 volumio volumio[1477]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 08 10:09:33 volumio go-librespot[1896]: time="2026-02-08T10:09:33+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Feb 08 10:09:33 volumio go-librespot[1896]: time="2026-02-08T10:09:33+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 464" Feb 08 10:09:33 volumio go-librespot[1896]: time="2026-02-08T10:09:33+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 08 10:09:33 volumio go-librespot[1896]: time="2026-02-08T10:09:33+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1443" Feb 08 10:09:33 volumio go-librespot[1896]: time="2026-02-08T10:09:33+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 08 10:09:33 volumio go-librespot[1896]: time="2026-02-08T10:09:33+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1201" Feb 08 10:09:33 volumio volumio[1477]: info: Initializing connection to go-librespot Websocket Feb 08 10:09:33 volumio go-librespot[1896]: time="2026-02-08T10:09:33+01:00" level=debug msg="new websocket client" Feb 08 10:09:34 volumio sudo[2174]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 08 10:09:34 volumio sudo[2174]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 10:09:34 volumio sudo[2174]: pam_unix(sudo:session): session closed for user root Feb 08 10:09:34 volumio sudo[2176]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 08 10:09:34 volumio sudo[2176]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 10:09:34 volumio sudo[2176]: pam_unix(sudo:session): session closed for user root Feb 08 10:09:34 volumio volumio[1477]: info: Connection to go-librespot Websocket established Feb 08 10:09:34 volumio volumio[1477]: info: Volumio Network Manager: Network status updated: 2 Feb 08 10:09:34 volumio sudo[2180]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 08 10:09:34 volumio sudo[2180]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 10:09:34 volumio systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Feb 08 10:09:34 volumio systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Feb 08 10:09:34 volumio systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Feb 08 10:09:34 volumio systemd[1]: dpkg-db-backup.service: Deactivated successfully. Feb 08 10:09:34 volumio systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Feb 08 10:09:36 volumio kernel: hwmon hwmon3: Voltage normalised Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Feb 08 10:09:36 volumio volumio[1477]: info: Adding plugin bluetooth to MyMusic Plugins Feb 08 10:09:36 volumio volumio[1477]: info: Adding plugin multiroom to MyMusic Plugins Feb 08 10:09:36 volumio volumio[1477]: info: Adding plugin metavolumio to MyMusic Plugins Feb 08 10:09:36 volumio volumio[1477]: info: Adding plugin cd_controller to MyMusic Plugins Feb 08 10:09:36 volumio volumio[1477]: info: Adding plugin qobuzconnect to MyMusic Plugins Feb 08 10:09:36 volumio volumio[1477]: info: Adding plugin smart_inputs to MyMusic Plugins Feb 08 10:09:36 volumio volumio[1477]: info: Adding plugin tidalconnect to MyMusic Plugins Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=debug msg="handling transfer player command from 1c41b2190f46d3171d9194df776f2d392114cb31" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=debug msg="resolved context of track" uri="spotify:artist:2SHhfs4BiDxGQ3oxqf0UHY" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=trace msg="fetched new page 0 with 10 items (list: 10)" uri="spotify:artist:2SHhfs4BiDxGQ3oxqf0UHY" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=trace msg="fetched new page 1 with 41 items (list: 51)" uri="spotify:artist:2SHhfs4BiDxGQ3oxqf0UHY" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=debug msg="loading track (paused: true, position: 0ms)" uri="spotify:track:2MaBAGBIttgv86bYytdx1f" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=trace msg="emitting websocket event: will_play" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1130" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=debug msg="selected format OGG_VORBIS_320 (65ef00cc1e61b4f6bd3371bda366e86aeef32072)" uri="spotify:track:2MaBAGBIttgv86bYytdx1f" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=debug msg="requested aes key for file 65ef00cc1e61b4f6bd3371bda366e86aeef32072, gid: 2MaBAGBIttgv86bYytdx1f" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:2MaBAGBIttgv86bYytdx1f" Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Feb 08 10:09:36 volumio volumio[1477]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 10:09:36 volumio volumio[1477]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 10:09:36 volumio volumio[1477]: info: Starting MyVolumio Remote Streaming Endpoints Feb 08 10:09:36 volumio volumio[1477]: info: MyVolumio login type: Token Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Feb 08 10:09:36 volumio volumio[1477]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=debug msg="fetched first chunk of 25, total size is 13037216 bytes" uri="spotify:track:2MaBAGBIttgv86bYytdx1f" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=debug msg="created new output device" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=info msg="loaded track \"Listen To Your Heart\" (paused: true, position: 0ms, duration: 328093ms, prefetched: false)" uri="spotify:track:2MaBAGBIttgv86bYytdx1f" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=trace msg="emitting websocket event: metadata" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=trace msg="emitting websocket event: active" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=debug msg="sending successful reply for dealer request" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=debug msg="fetched chunk 3/24, size: 524288" uri="spotify:track:2MaBAGBIttgv86bYytdx1f" Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Feb 08 10:09:36 volumio go-librespot[1896]: time="2026-02-08T10:09:36+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 08 10:09:37 volumio go-librespot[1896]: time="2026-02-08T10:09:37+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 08 10:09:37 volumio go-librespot[1896]: time="2026-02-08T10:09:37+01:00" level=trace msg="emitting websocket event: paused" Feb 08 10:09:37 volumio volumio[1477]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Feb 08 10:09:37 volumio volumio[1477]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Feb 08 10:09:37 volumio volumio[1477]: info: Streaming services startup Feb 08 10:09:37 volumio volumio[1477]: info: Starting Streaming Daemon Feb 08 10:09:37 volumio sudo[2195]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 08 10:09:37 volumio sudo[2195]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 10:09:37 volumio volumio[1477]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Feb 08 10:09:37 volumio sudo[2195]: pam_unix(sudo:session): session closed for user root Feb 08 10:09:37 volumio volumio[1477]: info: Discovery: Started advertising with name: Volumio Feb 08 10:09:37 volumio go-librespot[1896]: time="2026-02-08T10:09:37+01:00" level=debug msg="fetched chunk 1/24, size: 524288" uri="spotify:track:2MaBAGBIttgv86bYytdx1f" Feb 08 10:09:37 volumio go-librespot[1896]: time="2026-02-08T10:09:37+01:00" level=debug msg="fetched chunk 2/24, size: 524288" uri="spotify:track:2MaBAGBIttgv86bYytdx1f" Feb 08 10:09:37 volumio volumio[1477]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:artist:2SHhfs4BiDxGQ3oxqf0UHY","uri":"spotify:track:2MaBAGBIttgv86bYytdx1f","play_origin":"free-tier-artist"}} Feb 08 10:09:37 volumio volumio[1477]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2MaBAGBIttgv86bYytdx1f","name":"Listen To Your Heart","artist_names":["Roxette"],"album_name":"Look Sharp!","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0222c3c99e7aa0ba6cd08a6be6","position":0,"duration":328093,"release_date":"year:1988 month:10 day:21","track_number":13,"disc_number":1}} Feb 08 10:09:37 volumio volumio[1477]: SPOTIFY: received: {"type":"active","data":null} Feb 08 10:09:37 volumio volumio[1477]: info: Aligning Spotify Volume to Volumio Volume Feb 08 10:09:37 volumio volumio[1477]: info: CoreCommandRouter::volumioGetState Feb 08 10:09:37 volumio volumio[1477]: info: CorePlayQueue::getTrack 0 Feb 08 10:09:37 volumio volumio[1477]: info: Setting Spotify Volume from Volumio: 0 Feb 08 10:09:37 volumio volumio[1477]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:artist:2SHhfs4BiDxGQ3oxqf0UHY","uri":"spotify:track:2MaBAGBIttgv86bYytdx1f","play_origin":"free-tier-artist"}} Feb 08 10:09:37 volumio volumio[1477]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 08 10:09:37 volumio volumio[1477]: TypeError: Cannot read properties of undefined (reading 'service') Feb 08 10:09:37 volumio volumio[1477]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Feb 08 10:09:37 volumio volumio[1477]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:280:18) Feb 08 10:09:37 volumio volumio[1477]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Feb 08 10:09:37 volumio volumio[1477]: at WebSocket.emit (node:events:514:28) Feb 08 10:09:37 volumio volumio[1477]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Feb 08 10:09:37 volumio volumio[1477]: at Receiver.emit (node:events:514:28) Feb 08 10:09:37 volumio volumio[1477]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Feb 08 10:09:37 volumio volumio[1477]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Feb 08 10:09:37 volumio volumio[1477]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Feb 08 10:09:37 volumio volumio[1477]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Feb 08 10:09:37 volumio volumio[1477]: at writeOrBuffer (node:internal/streams/writable:399:12) Feb 08 10:09:37 volumio volumio[1477]: at _write (node:internal/streams/writable:340:10) Feb 08 10:09:37 volumio volumio[1477]: at Writable.write (node:internal/streams/writable:344:10) Feb 08 10:09:37 volumio volumio[1477]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Feb 08 10:09:37 volumio volumio[1477]: at Socket.emit (node:events:514:28) Feb 08 10:09:37 volumio volumio[1477]: at addChunk (node:internal/streams/readable:343:12) Feb 08 10:09:37 volumio volumio[1477]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 08 10:09:37 volumio sudo[2217]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-08 10:08' Feb 08 10:09:37 volumio sudo[2217]: 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="b05a530ca81d05eb9a84d0acf82089f0a60b8ee6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="4ad85e2147d972f0b838d33c21382d2d813b2ae8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Dec 25 09:13:19 UTC 2025" VOLUMIO_VERSION="4.084" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="792f09af7488531aecd1aadcaa9b175e"