-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Fri 2026-02-27 00:11:23 CET. -- Feb 27 00:10:05 volumio go-librespot[1384]: time="2026-02-27T00:10:05+01:00" level=debug msg="fetched chunk 10/22, size: 524288" uri="spotify:track:6EFVCBRoInFA89V4wCwu9m" Feb 27 00:10:13 volumio go-librespot[1384]: time="2026-02-27T00:10:13+01:00" level=trace msg="sent dealer ping" Feb 27 00:10:13 volumio go-librespot[1384]: time="2026-02-27T00:10:13+01:00" level=trace msg="received dealer pong" Feb 27 00:10:13 volumio go-librespot[1384]: time="2026-02-27T00:10:13+01:00" level=trace msg="received accesspoint ping" Feb 27 00:10:13 volumio go-librespot[1384]: time="2026-02-27T00:10:13+01:00" level=trace msg="received accesspoint pong ack" Feb 27 00:10:18 volumio go-librespot[1384]: time="2026-02-27T00:10:18+01:00" level=debug msg="fetched chunk 11/22, size: 524288" uri="spotify:track:6EFVCBRoInFA89V4wCwu9m" Feb 27 00:10:20 volumio go-librespot[1384]: time="2026-02-27T00:10:20+01:00" level=debug msg="handling skip_next player command from f261d3d172a94ec7d3fb2b18e8d3b970750ddf98" Feb 27 00:10:20 volumio go-librespot[1384]: time="2026-02-27T00:10:20+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:27rQhrLDEOYIdQ21J5xpE1" Feb 27 00:10:20 volumio go-librespot[1384]: time="2026-02-27T00:10:20+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 27 00:10:20 volumio go-librespot[1384]: time="2026-02-27T00:10:20+01:00" level=trace msg="emitting websocket event: will_play" Feb 27 00:10:20 volumio volumio[1004]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:03ydHbfrcyK4PaObBiWHBl","uri":"spotify:track:27rQhrLDEOYIdQ21J5xpE1","play_origin":"playlist/ondemand"}} Feb 27 00:10:20 volumio go-librespot[1384]: time="2026-02-27T00:10:20+01:00" level=debug msg="selected format OGG_VORBIS_320 (77b30d348f97c1c9b41716faa3d73a0ac8871e41)" uri="spotify:track:27rQhrLDEOYIdQ21J5xpE1" Feb 27 00:10:20 volumio go-librespot[1384]: time="2026-02-27T00:10:20+01:00" level=debug msg="requested aes key for file 77b30d348f97c1c9b41716faa3d73a0ac8871e41, gid: 27rQhrLDEOYIdQ21J5xpE1" Feb 27 00:10:20 volumio go-librespot[1384]: time="2026-02-27T00:10:20+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:27rQhrLDEOYIdQ21J5xpE1" Feb 27 00:10:20 volumio go-librespot[1384]: time="2026-02-27T00:10:20+01:00" level=debug msg="fetched first chunk of 12, total size is 6089872 bytes" uri="spotify:track:27rQhrLDEOYIdQ21J5xpE1" Feb 27 00:10:20 volumio go-librespot[1384]: time="2026-02-27T00:10:20+01:00" level=info msg="loaded track \"RIDGEWALK\" (paused: false, position: 0ms, duration: 147692ms, prefetched: false)" uri="spotify:track:27rQhrLDEOYIdQ21J5xpE1" Feb 27 00:10:20 volumio go-librespot[1384]: time="2026-02-27T00:10:20+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 27 00:10:20 volumio go-librespot[1384]: time="2026-02-27T00:10:20+01:00" level=trace msg="scheduling prefetch in 118s" Feb 27 00:10:20 volumio go-librespot[1384]: time="2026-02-27T00:10:20+01:00" level=trace msg="emitting websocket event: metadata" Feb 27 00:10:20 volumio go-librespot[1384]: time="2026-02-27T00:10:20+01:00" level=debug msg="sending successful reply for dealer request" Feb 27 00:10:20 volumio volumio[1004]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:27rQhrLDEOYIdQ21J5xpE1","name":"RIDGEWALK","artist_names":["Moses Yoofee Trio"],"album_name":"MYT","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0222140fc1346e579ca320af34","position":0,"duration":147692,"release_date":"year:2025 month:2 day:7","track_number":2,"disc_number":1}} Feb 27 00:10:20 volumio go-librespot[1384]: time="2026-02-27T00:10:20+01:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:27rQhrLDEOYIdQ21J5xpE1" Feb 27 00:10:20 volumio go-librespot[1384]: time="2026-02-27T00:10:20+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 27 00:10:20 volumio go-librespot[1384]: time="2026-02-27T00:10:20+01:00" level=trace msg="emitting websocket event: playing" Feb 27 00:10:20 volumio volumio[1004]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:03ydHbfrcyK4PaObBiWHBl","uri":"spotify:track:27rQhrLDEOYIdQ21J5xpE1","resume":false,"play_origin":"playlist/ondemand"}} Feb 27 00:10:20 volumio volumio[1004]: SPOTIFY: PUSH STATE SPOTIFY Feb 27 00:10:20 volumio volumio[1004]: SPOTIFY: {"status":"play","service":"spop","title":"RIDGEWALK","artist":"Moses Yoofee Trio","album":"MYT","albumart":"https://i.scdn.co/image/ab67616d00001e0222140fc1346e579ca320af34","uri":"spotify:track:27rQhrLDEOYIdQ21J5xpE1","trackType":"spotify","seek":0,"duration":147,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Feb 27 00:10:20 volumio volumio[1004]: info: CoreCommandRouter::servicePushState Feb 27 00:10:20 volumio volumio[1004]: info: CoreStateMachine::pushState Feb 27 00:10:20 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 27 00:10:20 volumio volumio[1004]: info: CoreCommandRouter::volumioPushState Feb 27 00:10:20 volumio volumio5-onboarding[1645]: time=2026-02-27T00:10:20.801+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.21:56252 @ 0x38f4030" state=STATUS_PLAYING positionMs=0 volume=100 Feb 27 00:10:20 volumio volumio5-onboarding[1645]: time=2026-02-27T00:10:20.801+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.21:56252 @ 0x38f4030" id=spotify:track:27rQhrLDEOYIdQ21J5xpE1 title=RIDGEWALK Feb 27 00:10:20 volumio volumio[1004]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 27 00:10:21 volumio volumio[1004]: SPOTIFY: PUSH STATE SPOTIFY Feb 27 00:10:21 volumio volumio[1004]: SPOTIFY: {"status":"play","service":"spop","title":"RIDGEWALK","artist":"Moses Yoofee Trio","album":"MYT","albumart":"https://i.scdn.co/image/ab67616d00001e0222140fc1346e579ca320af34","uri":"spotify:track:27rQhrLDEOYIdQ21J5xpE1","trackType":"spotify","seek":0,"duration":147,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Feb 27 00:10:21 volumio volumio[1004]: info: CoreCommandRouter::servicePushState Feb 27 00:10:21 volumio volumio[1004]: info: CoreStateMachine::pushState Feb 27 00:10:21 volumio volumio[1004]: info: CoreCommandRouter::volumioPushState Feb 27 00:10:21 volumio volumio5-onboarding[1645]: time=2026-02-27T00:10:21.101+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.21:56252 @ 0x38f4030" state=STATUS_PLAYING positionMs=0 volume=100 Feb 27 00:10:21 volumio volumio5-onboarding[1645]: time=2026-02-27T00:10:21.101+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.21:56252 @ 0x38f4030" id=spotify:track:27rQhrLDEOYIdQ21J5xpE1 title=RIDGEWALK Feb 27 00:10:21 volumio volumio[1004]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 27 00:10:21 volumio go-librespot[1384]: time="2026-02-27T00:10:21+01:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:27rQhrLDEOYIdQ21J5xpE1" Feb 27 00:10:21 volumio go-librespot[1384]: time="2026-02-27T00:10:21+01:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:27rQhrLDEOYIdQ21J5xpE1" Feb 27 00:10:33 volumio go-librespot[1384]: time="2026-02-27T00:10:33+01:00" level=debug msg="fetched chunk 4/11, size: 524288" uri="spotify:track:27rQhrLDEOYIdQ21J5xpE1" Feb 27 00:10:43 volumio go-librespot[1384]: time="2026-02-27T00:10:43+01:00" level=trace msg="sent dealer ping" Feb 27 00:10:43 volumio go-librespot[1384]: time="2026-02-27T00:10:43+01:00" level=trace msg="received dealer pong" Feb 27 00:10:45 volumio go-librespot[1384]: time="2026-02-27T00:10:45+01:00" level=debug msg="fetched chunk 5/11, size: 524288" uri="spotify:track:27rQhrLDEOYIdQ21J5xpE1" Feb 27 00:10:56 volumio go-librespot[1384]: time="2026-02-27T00:10:56+01:00" level=debug msg="fetched chunk 6/11, size: 524288" uri="spotify:track:27rQhrLDEOYIdQ21J5xpE1" Feb 27 00:11:08 volumio go-librespot[1384]: time="2026-02-27T00:11:08+01:00" level=debug msg="fetched chunk 7/11, size: 524288" uri="spotify:track:27rQhrLDEOYIdQ21J5xpE1" Feb 27 00:11:12 volumio go-librespot[1384]: time="2026-02-27T00:11:12+01:00" level=debug msg="handling pause player command from f261d3d172a94ec7d3fb2b18e8d3b970750ddf98" Feb 27 00:11:12 volumio go-librespot[1384]: time="2026-02-27T00:11:12+01:00" level=debug msg="pause track at 51925ms" Feb 27 00:11:12 volumio go-librespot[1384]: time="2026-02-27T00:11:12+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 27 00:11:12 volumio go-librespot[1384]: time="2026-02-27T00:11:12+01:00" level=debug msg="sending successful reply for dealer request" Feb 27 00:11:12 volumio go-librespot[1384]: time="2026-02-27T00:11:12+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 27 00:11:12 volumio go-librespot[1384]: time="2026-02-27T00:11:12+01:00" level=trace msg="emitting websocket event: paused" Feb 27 00:11:12 volumio volumio[1004]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:playlist:03ydHbfrcyK4PaObBiWHBl","uri":"spotify:track:27rQhrLDEOYIdQ21J5xpE1","play_origin":"playlist/ondemand"}} Feb 27 00:11:12 volumio volumio[1004]: SPOTIFY: PUSH STATE SPOTIFY Feb 27 00:11:12 volumio volumio[1004]: SPOTIFY: {"status":"pause","service":"spop","title":"RIDGEWALK","artist":"Moses Yoofee Trio","album":"MYT","albumart":"https://i.scdn.co/image/ab67616d00001e0222140fc1346e579ca320af34","uri":"spotify:track:27rQhrLDEOYIdQ21J5xpE1","trackType":"spotify","seek":51000,"duration":147,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Feb 27 00:11:12 volumio volumio[1004]: info: CoreCommandRouter::servicePushState Feb 27 00:11:12 volumio volumio[1004]: info: CoreStateMachine::pushState Feb 27 00:11:12 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 27 00:11:12 volumio volumio[1004]: info: CoreCommandRouter::volumioPushState Feb 27 00:11:12 volumio volumio5-onboarding[1645]: time=2026-02-27T00:11:12.616+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.21:56252 @ 0x38f4030" state=STATUS_PAUSED positionMs=51000 volume=100 Feb 27 00:11:12 volumio volumio[1004]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 27 00:11:12 volumio volumio5-onboarding[1645]: time=2026-02-27T00:11:12.618+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.21:56252 @ 0x38f4030" id=spotify:track:27rQhrLDEOYIdQ21J5xpE1 title=RIDGEWALK Feb 27 00:11:13 volumio go-librespot[1384]: time="2026-02-27T00:11:13+01:00" level=trace msg="sent dealer ping" Feb 27 00:11:13 volumio go-librespot[1384]: time="2026-02-27T00:11:13+01:00" level=trace msg="received dealer pong" Feb 27 00:11:18 volumio volumio[1004]: verbose: New Socket.io Connection to 192.168.178.24 from 192.168.178.21 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 6 Feb 27 00:11:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 27 00:11:18 volumio volumio[1004]: info: CoreCommandRouter::volumioGetVisibleSources Feb 27 00:11:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 27 00:11:18 volumio volumio[1004]: info: CoreCommandRouter::volumioGetState Feb 27 00:11:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 27 00:11:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 27 00:11:18 volumio volumio[1004]: info: Received Get System Info Feb 27 00:11:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 27 00:11:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 27 00:11:18 volumio volumio[1004]: info: Discovery: Getting this device information Feb 27 00:11:18 volumio volumio[1004]: info: CoreCommandRouter::volumioGetState Feb 27 00:11:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 27 00:11:18 volumio volumio[1004]: info: CoreCommandRouter::volumioGetState Feb 27 00:11:18 volumio volumio[1004]: info: Listing playlists Feb 27 00:11:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Feb 27 00:11:23 volumio volumio[1004]: info: ___________ PLUGINS: Run Shutdown Tasks ___________ Feb 27 00:11:23 volumio volumio[1004]: info: PLUGIN onShutdown : networkfs Feb 27 00:11:23 volumio volumio[1004]: info: PLUGIN onShutdown : audiophonicsonoff Feb 27 00:11:23 volumio volumio[1004]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 27 00:11:23 volumio volumio[1004]: TypeError: Cannot read property 'writeSync' of undefined Feb 27 00:11:23 volumio volumio[1004]: at ControllerAudiophonicsOnOff.onVolumioShutdown (/data/plugins/system_hardware/audiophonicsonoff/index.js:48:25) Feb 27 00:11:23 volumio volumio[1004]: at PluginManager.onVolumioShutdownPlugin (/volumio/app/pluginmanager.js:638:30) Feb 27 00:11:23 volumio volumio[1004]: at HashMap. (/volumio/app/pluginmanager.js:621:31) Feb 27 00:11:23 volumio volumio[1004]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Feb 27 00:11:23 volumio volumio[1004]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Feb 27 00:11:23 volumio volumio[1004]: at PluginManager.onVolumioShutdown (/volumio/app/pluginmanager.js:619:20) Feb 27 00:11:23 volumio volumio[1004]: at CoreCommandRouter.shutdown (/volumio/app/index.js:1328:22) Feb 27 00:11:23 volumio volumio[1004]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:859:33) Feb 27 00:11:23 volumio volumio[1004]: at Socket.emit (events.js:315:20) Feb 27 00:11:23 volumio volumio[1004]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Feb 27 00:11:23 volumio volumio[1004]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Feb 27 00:11:23 volumio volumio[1004]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 27 00:11:23 volumio sudo[2728]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-02-27 00:10 Feb 27 00:11:23 volumio sudo[2728]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="e9612ec5034fb2e958508aaefbca2962fd6f6654" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 05 Feb 2026 01:46:18 PM CET" VOLUMIO_VERSION="3.908" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3e9dbaf8f44792d26e97456a18f12823"