-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Fri 2026-02-06 20:03:52 CET. -- Feb 06 20:02:03 volumio go-librespot[1303]: time="2026-02-06T20:02:03+01:00" level=trace msg="received accesspoint ping" Feb 06 20:02:03 volumio go-librespot[1303]: time="2026-02-06T20:02:03+01:00" level=trace msg="received accesspoint pong ack" Feb 06 20:02:03 volumio go-librespot[1303]: time="2026-02-06T20:02:03+01:00" level=trace msg="sent dealer ping" Feb 06 20:02:03 volumio go-librespot[1303]: time="2026-02-06T20:02:03+01:00" level=trace msg="received dealer pong" Feb 06 20:02:33 volumio go-librespot[1303]: time="2026-02-06T20:02:33+01:00" level=trace msg="sent dealer ping" Feb 06 20:02:33 volumio go-librespot[1303]: time="2026-02-06T20:02:33+01:00" level=trace msg="received dealer pong" Feb 06 20:03:03 volumio go-librespot[1303]: time="2026-02-06T20:03:03+01:00" level=trace msg="sent dealer ping" Feb 06 20:03:03 volumio go-librespot[1303]: time="2026-02-06T20:03:03+01:00" level=trace msg="received dealer pong" Feb 06 20:03:06 volumio volumio[976]: info: CoreCommandRouter::volumioPlay Feb 06 20:03:06 volumio volumio[976]: info: CoreStateMachine::play index undefined Feb 06 20:03:06 volumio volumio[976]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 06 20:03:06 volumio volumio[976]: info: CorePlayQueue::getTrack 3 Feb 06 20:03:06 volumio volumio[976]: info: CoreStateMachine::startPlaybackTimer Feb 06 20:03:06 volumio volumio[976]: info: CorePlayQueue::getTrack 3 Feb 06 20:03:06 volumio volumio[976]: info: [1770404586815] ControllerSpotify::clearAddPlayTrack Feb 06 20:03:06 volumio volumio[976]: info: Sending Spotify command with payload to local API: /player/play Feb 06 20:03:06 volumio go-librespot[1303]: time="2026-02-06T20:03:06+01:00" level=debug msg="resolved context of track" uri="spotify:track:7ixCRBD0FZMRBeOBhTu2KD" Feb 06 20:03:06 volumio go-librespot[1303]: time="2026-02-06T20:03:06+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7ixCRBD0FZMRBeOBhTu2KD" Feb 06 20:03:06 volumio go-librespot[1303]: time="2026-02-06T20:03:06+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7ixCRBD0FZMRBeOBhTu2KD" Feb 06 20:03:06 volumio go-librespot[1303]: time="2026-02-06T20:03:06+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 06 20:03:06 volumio go-librespot[1303]: time="2026-02-06T20:03:06+01:00" level=trace msg="emitting websocket event: will_play" Feb 06 20:03:06 volumio volumio[976]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7ixCRBD0FZMRBeOBhTu2KD","play_origin":"go-librespot"}} Feb 06 20:03:06 volumio go-librespot[1303]: time="2026-02-06T20:03:06+01:00" level=warning msg="original track has no formats, alternatives have a total of 0" uri="spotify:track:7ixCRBD0FZMRBeOBhTu2KD" Feb 06 20:03:06 volumio go-librespot[1303]: time="2026-02-06T20:03:06+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:7ixCRBD0FZMRBeOBhTu2KD: no supported formats" Feb 06 20:03:06 volumio volumio[976]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 06 20:03:07 volumio volumio[976]: info: CoreCommandRouter::volumioPlay Feb 06 20:03:07 volumio volumio[976]: info: CoreStateMachine::play index undefined Feb 06 20:03:07 volumio volumio[976]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 06 20:03:07 volumio volumio[976]: info: CorePlayQueue::getTrack 3 Feb 06 20:03:07 volumio volumio[976]: info: CoreStateMachine::startPlaybackTimer Feb 06 20:03:07 volumio volumio[976]: info: CorePlayQueue::getTrack 3 Feb 06 20:03:07 volumio volumio[976]: info: [1770404587910] ControllerSpotify::clearAddPlayTrack Feb 06 20:03:07 volumio volumio[976]: info: Sending Spotify command with payload to local API: /player/play Feb 06 20:03:07 volumio go-librespot[1303]: time="2026-02-06T20:03:07+01:00" level=debug msg="resolved context of track" uri="spotify:track:7ixCRBD0FZMRBeOBhTu2KD" Feb 06 20:03:07 volumio go-librespot[1303]: time="2026-02-06T20:03:07+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7ixCRBD0FZMRBeOBhTu2KD" Feb 06 20:03:07 volumio go-librespot[1303]: time="2026-02-06T20:03:07+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7ixCRBD0FZMRBeOBhTu2KD" Feb 06 20:03:07 volumio go-librespot[1303]: time="2026-02-06T20:03:07+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 06 20:03:07 volumio go-librespot[1303]: time="2026-02-06T20:03:07+01:00" level=trace msg="emitting websocket event: will_play" Feb 06 20:03:07 volumio volumio[976]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7ixCRBD0FZMRBeOBhTu2KD","play_origin":"go-librespot"}} Feb 06 20:03:07 volumio go-librespot[1303]: time="2026-02-06T20:03:07+01:00" level=warning msg="original track has no formats, alternatives have a total of 0" uri="spotify:track:7ixCRBD0FZMRBeOBhTu2KD" Feb 06 20:03:07 volumio go-librespot[1303]: time="2026-02-06T20:03:07+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:7ixCRBD0FZMRBeOBhTu2KD: no supported formats" Feb 06 20:03:07 volumio volumio[976]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 06 20:03:08 volumio volumio[976]: info: CoreCommandRouter::volumioPlay Feb 06 20:03:08 volumio volumio[976]: info: CoreStateMachine::play index undefined Feb 06 20:03:08 volumio volumio[976]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 06 20:03:08 volumio volumio[976]: info: CorePlayQueue::getTrack 3 Feb 06 20:03:08 volumio volumio[976]: info: CoreStateMachine::startPlaybackTimer Feb 06 20:03:08 volumio volumio[976]: info: CorePlayQueue::getTrack 3 Feb 06 20:03:08 volumio volumio[976]: info: [1770404588360] ControllerSpotify::clearAddPlayTrack Feb 06 20:03:08 volumio volumio[976]: info: Sending Spotify command with payload to local API: /player/play Feb 06 20:03:08 volumio go-librespot[1303]: time="2026-02-06T20:03:08+01:00" level=debug msg="resolved context of track" uri="spotify:track:7ixCRBD0FZMRBeOBhTu2KD" Feb 06 20:03:08 volumio go-librespot[1303]: time="2026-02-06T20:03:08+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7ixCRBD0FZMRBeOBhTu2KD" Feb 06 20:03:08 volumio go-librespot[1303]: time="2026-02-06T20:03:08+01:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:7ixCRBD0FZMRBeOBhTu2KD" Feb 06 20:03:08 volumio go-librespot[1303]: time="2026-02-06T20:03:08+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 06 20:03:08 volumio go-librespot[1303]: time="2026-02-06T20:03:08+01:00" level=trace msg="emitting websocket event: will_play" Feb 06 20:03:08 volumio volumio[976]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7ixCRBD0FZMRBeOBhTu2KD","play_origin":"go-librespot"}} Feb 06 20:03:08 volumio go-librespot[1303]: time="2026-02-06T20:03:08+01:00" level=warning msg="original track has no formats, alternatives have a total of 0" uri="spotify:track:7ixCRBD0FZMRBeOBhTu2KD" Feb 06 20:03:08 volumio go-librespot[1303]: time="2026-02-06T20:03:08+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:7ixCRBD0FZMRBeOBhTu2KD: no supported formats" Feb 06 20:03:08 volumio volumio[976]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 06 20:03:17 volumio volumio-remote-updater[591]: No test mode Feb 06 20:03:17 volumio volumio-remote-updater[591]: No alpha test mode Feb 06 20:03:17 volumio volumio[976]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Feb 06 20:03:17 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Feb 06 20:03:20 volumio volumio[976]: info: CoreCommandRouter::Close All Modals sent Feb 06 20:03:33 volumio go-librespot[1303]: time="2026-02-06T20:03:33+01:00" level=trace msg="sent dealer ping" Feb 06 20:03:33 volumio go-librespot[1303]: time="2026-02-06T20:03:33+01:00" level=trace msg="received dealer pong" Feb 06 20:03:44 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: alarm-clock , getSleep Feb 06 20:03:52 volumio volumio[976]: info: ___________ PLUGINS: Run onVolumioReboot Tasks ___________ Feb 06 20:03:52 volumio volumio[976]: info: PLUGIN onReboot : networkfs Feb 06 20:03:52 volumio volumio[976]: info: PLUGIN onReboot : audiophonicsonoff Feb 06 20:03:52 volumio volumio[976]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 06 20:03:52 volumio volumio[976]: TypeError: Cannot read property 'writeSync' of undefined Feb 06 20:03:52 volumio volumio[976]: at ControllerAudiophonicsOnOff.onVolumioReboot (/data/plugins/system_hardware/audiophonicsonoff/index.js:40:25) Feb 06 20:03:52 volumio volumio[976]: at PluginManager.onVolumioRebootPlugin (/volumio/app/pluginmanager.js:684:30) Feb 06 20:03:52 volumio volumio[976]: at HashMap. (/volumio/app/pluginmanager.js:668:31) Feb 06 20:03:52 volumio volumio[976]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Feb 06 20:03:52 volumio volumio[976]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Feb 06 20:03:52 volumio volumio[976]: at PluginManager.onVolumioReboot (/volumio/app/pluginmanager.js:666:20) Feb 06 20:03:52 volumio volumio[976]: at CoreCommandRouter.reboot (/volumio/app/index.js:1350:22) Feb 06 20:03:52 volumio volumio[976]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:870:33) Feb 06 20:03:52 volumio volumio[976]: at Socket.emit (events.js:315:20) Feb 06 20:03:52 volumio volumio[976]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Feb 06 20:03:52 volumio volumio[976]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Feb 06 20:03:52 volumio volumio[976]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 06 20:03:52 volumio sudo[4639]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-02-06 20:02 Feb 06 20:03:52 volumio sudo[4639]: 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="b43c85cc0006d3f1efecba101311ec96e334d1fd" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 11 Dec 2025 05:43:24 PM CET" VOLUMIO_VERSION="3.886" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="15d0241b0cd805792809f3ddf4a0fc4e"