Feb 08 19:05:00 audio volumio[1210]: info: Preload queue cleared Feb 08 19:05:00 audio volumio[1210]: info: CoreCommandRouter::volumioReplaceandPlayItems Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::ClearQueue Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::stop Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::updateTrackBlock Feb 08 19:05:00 audio volumio[1210]: info: CorePlayQueue::getTrackBlock Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::stPlaybackTimer Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::pushState Feb 08 19:05:00 audio volumio[1210]: info: CorePlayQueue::getTrack 0 Feb 08 19:05:00 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 08 19:05:00 audio volumio[1210]: info: CoreCommandRouter::volumioPushState Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::serviceStop Feb 08 19:05:00 audio volumio[1210]: info: CorePlayQueue::getTrack 0 Feb 08 19:05:00 audio volumio[1210]: info: CoreCommandRouter::serviceStop Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::setConsumeUpdateService mpd Feb 08 19:05:00 audio volumio[1210]: info: ControllerMpd::stop Feb 08 19:05:00 audio volumio[1210]: verbose: ControllerMpd::sendMpdCommand stop Feb 08 19:05:00 audio volumio[1210]: info: CorePlayQueue::clearPlayQueue Feb 08 19:05:00 audio volumio[1210]: info: CorePlayQueue::saveQueue Feb 08 19:05:00 audio volumio[1210]: info: CoreCommandRouter::volumioPushQueue Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::addQueueItems Feb 08 19:05:00 audio volumio[1210]: info: CorePlayQueue::addQueueItems Feb 08 19:05:00 audio volumio[1210]: info: Preload queue cleared Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:2KVu8tEUwAGu4TnnIgCiZW Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:2KVu8tEUwAGu4TnnIgCiZW Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:7DonHcAdu5FHzLNESEEOuj Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:7DonHcAdu5FHzLNESEEOuj Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:18TBMMOs1NICUt1sQfCeuQ Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:18TBMMOs1NICUt1sQfCeuQ Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:6JsOgTnOGoiuS8j8zSKH4j Feb 08 19:05:00 audio volumio[1210]: info: Exploding uri spotify:track:6JsOgTnOGoiuS8j8zSKH4j in service spop Feb 08 19:05:00 audio volumio[1210]: SPOTIFY: EXPLODING URI:spotify:track:6JsOgTnOGoiuS8j8zSKH4j Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:6zEv4Vh4Pvvq3p5ptQ1Vu6 Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:6zEv4Vh4Pvvq3p5ptQ1Vu6 Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:2GzjIHQ87BF2zgbmmthZzO Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:2GzjIHQ87BF2zgbmmthZzO Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:59mAkKONcJ9m5l6AlG7xGZ Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:59mAkKONcJ9m5l6AlG7xGZ Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:5PqWYF5P9fmCQmxRt5eoZD Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:5PqWYF5P9fmCQmxRt5eoZD Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:5XseQZ9TGr06Rv1Ye6wCu0 Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:5XseQZ9TGr06Rv1Ye6wCu0 Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:6iK2pxK4fCJLZwrzUslWgY Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:6iK2pxK4fCJLZwrzUslWgY Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:2UeKSW9EMKyosFq52MnbwH Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:2UeKSW9EMKyosFq52MnbwH Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:4xmkpE1Si5JL7NFxWrhV0S Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:4xmkpE1Si5JL7NFxWrhV0S Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 08 19:05:00 audio volumio[1210]: info: sendMpdCommand stop took 42 milliseconds Feb 08 19:05:00 audio volumio[1210]: info: Feb 08 19:05:00 audio volumio[1210]: ---------------------------- MPD announces state update: player Feb 08 19:05:00 audio volumio[1210]: info: ControllerMpd::getState Feb 08 19:05:00 audio volumio[1210]: verbose: ControllerMpd::sendMpdCommand status Feb 08 19:05:00 audio volumio[1210]: info: Feb 08 19:05:00 audio volumio[1210]: ---------------------------- MPD announces state update: player Feb 08 19:05:00 audio volumio[1210]: info: ControllerMpd::getState Feb 08 19:05:00 audio volumio[1210]: verbose: ControllerMpd::sendMpdCommand status Feb 08 19:05:00 audio volumio[1210]: info: sendMpdCommand status took 3 milliseconds Feb 08 19:05:00 audio volumio[1210]: info: sendMpdCommand status took 2 milliseconds Feb 08 19:05:00 audio volumio[1210]: verbose: ControllerMpd::parseState Feb 08 19:05:00 audio volumio[1210]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 08 19:05:00 audio volumio[1210]: verbose: ControllerMpd::parseState Feb 08 19:05:00 audio volumio[1210]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 08 19:05:00 audio volumio[1210]: info: sendMpdCommand playlistinfo took 2 milliseconds Feb 08 19:05:00 audio volumio[1210]: info: sendMpdCommand playlistinfo took 2 milliseconds Feb 08 19:05:00 audio volumio[1210]: verbose: ControllerMpd::parseTrackInfo Feb 08 19:05:00 audio volumio[1210]: verbose: ControllerMpd::parseTrackInfo Feb 08 19:05:00 audio volumio[1210]: info: ControllerMpd::pushState Feb 08 19:05:00 audio volumio[1210]: info: CoreCommandRouter::servicePushState Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::pushState Feb 08 19:05:00 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 08 19:05:00 audio volumio[1210]: info: CoreCommandRouter::volumioPushState Feb 08 19:05:00 audio volumio[1210]: info: CorePlayQueue::getTrack 0 Feb 08 19:05:00 audio volumio[1210]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"DJ Seeker & Psycha - 883.centreforce DAB+ - 07 - 02 - 2026 .mp3","artist":"883 CENTREFORCE TV NETWORK","album":null,"uri":"https://audio.mixcloud.stream/secure/hls/,7/5/9/3/78be-cc5d-4ffb-aa9c-5fb6c1eabed6,7/5/9/3/78be-cc5d-4ffb-aa9c-5fb6c1eabed6-192K,.m4a.urlset/index.m3u8","trackType":"m3u8"} Feb 08 19:05:00 audio volumio[1210]: verbose: CURRENT POSITION 0 Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::syncState stateService stop Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::syncState currentStatus stop Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::pushState Feb 08 19:05:00 audio volumio[1210]: info: CoreCommandRouter::volumioPushState Feb 08 19:05:00 audio volumio[1210]: info: No code Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::pushState Feb 08 19:05:00 audio volumio[1210]: info: CoreCommandRouter::volumioPushState Feb 08 19:05:00 audio volumio[1210]: info: ControllerMpd::pushState Feb 08 19:05:00 audio volumio[1210]: info: CoreCommandRouter::servicePushState Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::pushState Feb 08 19:05:00 audio volumio[1210]: info: CoreCommandRouter::volumioPushState Feb 08 19:05:00 audio volumio[1210]: info: CorePlayQueue::getTrack 0 Feb 08 19:05:00 audio volumio[1210]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"DJ Seeker & Psycha - 883.centreforce DAB+ - 07 - 02 - 2026 .mp3","artist":"883 CENTREFORCE TV NETWORK","album":null,"uri":"https://audio.mixcloud.stream/secure/hls/,7/5/9/3/78be-cc5d-4ffb-aa9c-5fb6c1eabed6,7/5/9/3/78be-cc5d-4ffb-aa9c-5fb6c1eabed6-192K,.m4a.urlset/index.m3u8","trackType":"m3u8"} Feb 08 19:05:00 audio volumio[1210]: verbose: CURRENT POSITION 0 Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::syncState stateService stop Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::syncState currentStatus stop Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::pushState Feb 08 19:05:00 audio volumio[1210]: info: CoreCommandRouter::volumioPushState Feb 08 19:05:00 audio volumio[1210]: info: No code Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::pushState Feb 08 19:05:00 audio volumio[1210]: info: CoreCommandRouter::volumioPushState Feb 08 19:05:00 audio volumio[1210]: info: ------------------------------ 51ms Feb 08 19:05:00 audio volumio[1210]: info: ------------------------------ 52ms Feb 08 19:05:00 audio volumio[1210]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 08 19:05:00 audio volumio[1210]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 08 19:05:00 audio volumio[1210]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 08 19:05:00 audio volumio[1210]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 08 19:05:00 audio volumio[1210]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 08 19:05:00 audio volumio[1210]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 08 19:05:00 audio volumio[1210]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6JsOgTnOGoiuS8j8zSKH4j","service":"spop","name":"Aashiqon Ki Colony (From \"O' Romeo\")","artist":"Vishal Bhardwaj","album":"Aashiqon Ki Colony (From \"O' Romeo\")","type":"song","duration":301,"albumart":"https://i.scdn.co/image/ab67616d0000b2733a8ee1c483577b4a6a0dd934","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 08 19:05:00 audio volumio[1210]: info: CoreCommandRouter::volumioPushQueue Feb 08 19:05:00 audio volumio[1210]: info: CorePlayQueue::saveQueue Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::updateTrackBlock Feb 08 19:05:00 audio volumio[1210]: info: CorePlayQueue::getTrackBlock Feb 08 19:05:00 audio volumio[1210]: info: CoreCommandRouter::volumioPlay Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::play index 12 Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::addQueueItems Feb 08 19:05:00 audio volumio[1210]: info: CorePlayQueue::addQueueItems Feb 08 19:05:00 audio volumio[1210]: info: Preload queue cleared Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:6oCqQBfH9Vf9JELgAh6eKv Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:6oCqQBfH9Vf9JELgAh6eKv Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:6akoG8Qm3rlCIkF0BUEf2G Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:6akoG8Qm3rlCIkF0BUEf2G Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:6JsOgTnOGoiuS8j8zSKH4j Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:6JsOgTnOGoiuS8j8zSKH4j Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:4zZlZgX3sleF4h8XTnxY14 Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:4zZlZgX3sleF4h8XTnxY14 Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:3KYbbE5Yje5IcqJmNNbbkS Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:3KYbbE5Yje5IcqJmNNbbkS Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:0H545XfNvoSu9THGf8mBnd Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:0H545XfNvoSu9THGf8mBnd Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:2xyWyWbR6zN4rqsraUS1tm Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:2xyWyWbR6zN4rqsraUS1tm Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:6hiQgcVv74wTWK2ne40bP9 Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:6hiQgcVv74wTWK2ne40bP9 Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:1980E4Grgu5xAhNbFZ1mb1 Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:1980E4Grgu5xAhNbFZ1mb1 Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:26ku8sJ1rV2gQAEuNs38X6 Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:26ku8sJ1rV2gQAEuNs38X6 Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:5NK3IhIeIXQmOKK5EiSRra Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:5NK3IhIeIXQmOKK5EiSRra Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:1ypwNj8eK2qAMDEs4EiIIX Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:1ypwNj8eK2qAMDEs4EiIIX Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:7fZBQnc0zXwVybgCIrQQil Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:7fZBQnc0zXwVybgCIrQQil Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:0gzUB1TKV9yTIV9icQSwUm Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:0gzUB1TKV9yTIV9icQSwUm Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:6scnPzPV3aHgsusrG9uHMZ Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:6scnPzPV3aHgsusrG9uHMZ Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:5d3djY1StQoYgj6TZL19J2 Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:5d3djY1StQoYgj6TZL19J2 Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:5IYVXxbVppVRGC3G5LdmID Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:5IYVXxbVppVRGC3G5LdmID Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:1n6qxp6jO49U0o9QzKXHTz Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:1n6qxp6jO49U0o9QzKXHTz Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:1n6qxp6jO49U0o9QzKXHTz Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:1n6qxp6jO49U0o9QzKXHTz Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:5MCbGWnNLLjoHpbDO3BOgi Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:5MCbGWnNLLjoHpbDO3BOgi Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:3Zg5ENFvbucf41iPRvPcHn Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:3Zg5ENFvbucf41iPRvPcHn Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:2nnDPEbNxnBKq5RG6sObTg Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:3SVgtZSEqPNga5pKOJLCDZ Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:3SVgtZSEqPNga5pKOJLCDZ Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:2dQMisG0lyz6Z8J4zYdAsG Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:2dQMisG0lyz6Z8J4zYdAsG Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:6JIquezleHbiqFOSuvBlxw Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:6JIquezleHbiqFOSuvBlxw Feb 08 19:05:00 audio volumio[1210]: info: Adding Item to queue: spotify:track:0R7grQWU1dRxiOQGIqZm0Z Feb 08 19:05:00 audio volumio[1210]: info: Using cached record of: spotify:track:0R7grQWU1dRxiOQGIqZm0Z Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::stop Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 08 19:05:00 audio volumio[1210]: info: CoreCommandRouter::volumioPushQueue Feb 08 19:05:00 audio volumio[1210]: info: CorePlayQueue::saveQueue Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::play index undefined Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::updateTrackBlock Feb 08 19:05:00 audio volumio[1210]: info: CorePlayQueue::getTrackBlock Feb 08 19:05:00 audio volumio[1210]: info: CorePlayQueue::getTrack 12 Feb 08 19:05:00 audio volumio[1210]: info: CoreStateMachine::startPlaybackTimer Feb 08 19:05:00 audio volumio[1210]: info: CorePlayQueue::getTrack 12 Feb 08 19:05:00 audio volumio[1210]: info: [1770537900611] ControllerSpotify::clearAddPlayTrack Feb 08 19:05:00 audio volumio[1210]: info: Sending Spotify command with payload to local API: /player/play Feb 08 19:05:00 audio go-librespot[1563]: time="2026-02-08T19:05:00+11:00" level=debug msg="resolved context of track" uri="spotify:track:2nnDPEbNxnBKq5RG6sObTg" Feb 08 19:05:00 audio go-librespot[1563]: time="2026-02-08T19:05:00+11:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2nnDPEbNxnBKq5RG6sObTg" Feb 08 19:05:00 audio go-librespot[1563]: time="2026-02-08T19:05:00+11:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2nnDPEbNxnBKq5RG6sObTg" Feb 08 19:05:01 audio go-librespot[1563]: time="2026-02-08T19:05:01+11:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 08 19:05:01 audio go-librespot[1563]: time="2026-02-08T19:05:01+11:00" level=trace msg="emitting websocket event: will_play" Feb 08 19:05:01 audio volumio[1210]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2nnDPEbNxnBKq5RG6sObTg","uri":"spotify:track:2nnDPEbNxnBKq5RG6sObTg","play_origin":"go-librespot"}} Feb 08 19:05:01 audio go-librespot[1563]: time="2026-02-08T19:05:01+11:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Feb 08 19:05:01 audio go-librespot[1563]: time="2026-02-08T19:05:01+11:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Feb 08 19:05:01 audio go-librespot[1563]: time="2026-02-08T19:05:01+11:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 08 19:05:01 audio go-librespot[1563]: time="2026-02-08T19:05:01+11:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1322" Feb 08 19:05:01 audio go-librespot[1563]: time="2026-02-08T19:05:01+11:00" level=debug msg="selected format OGG_VORBIS_320 (dcbd078c817f3046fc4263369522f24ae9d6f78e)" uri="spotify:track:2nnDPEbNxnBKq5RG6sObTg" Feb 08 19:05:01 audio go-librespot[1563]: time="2026-02-08T19:05:01+11:00" level=debug msg="requested aes key for file dcbd078c817f3046fc4263369522f24ae9d6f78e, gid: 2nnDPEbNxnBKq5RG6sObTg" Feb 08 19:05:01 audio go-librespot[1563]: time="2026-02-08T19:05:01+11:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 08 19:05:01 audio go-librespot[1563]: time="2026-02-08T19:05:01+11:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1104" Feb 08 19:05:01 audio go-librespot[1563]: time="2026-02-08T19:05:01+11:00" level=trace msg="found 2 cdn urls" uri="spotify:track:2nnDPEbNxnBKq5RG6sObTg" Feb 08 19:05:01 audio go-librespot[1563]: time="2026-02-08T19:05:01+11:00" level=debug msg="fetched first chunk of 13, total size is 6460928 bytes" uri="spotify:track:2nnDPEbNxnBKq5RG6sObTg" Feb 08 19:05:01 audio go-librespot[1563]: time="2026-02-08T19:05:01+11:00" level=debug msg="created new output device" Feb 08 19:05:01 audio go-librespot[1563]: time="2026-02-08T19:05:01+11:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Feb 08 19:05:01 audio go-librespot[1563]: time="2026-02-08T19:05:01+11:00" level=info msg="loaded track \"Naal Nachna\" (paused: false, position: 0ms, duration: 155142ms, prefetched: false)" uri="spotify:track:2nnDPEbNxnBKq5RG6sObTg" Feb 08 19:05:01 audio go-librespot[1563]: time="2026-02-08T19:05:01+11:00" level=debug msg="fetched chunk 1/12, size: 524288" uri="spotify:track:2nnDPEbNxnBKq5RG6sObTg" Feb 08 19:05:02 audio go-librespot[1563]: time="2026-02-08T19:05:02+11:00" level=debug msg="fetched chunk 3/12, size: 524288" uri="spotify:track:2nnDPEbNxnBKq5RG6sObTg" Feb 08 19:05:02 audio go-librespot[1563]: time="2026-02-08T19:05:02+11:00" level=debug msg="fetched chunk 2/12, size: 524288" uri="spotify:track:2nnDPEbNxnBKq5RG6sObTg" Feb 08 19:05:02 audio go-librespot[1563]: time="2026-02-08T19:05:02+11:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 08 19:05:02 audio go-librespot[1563]: time="2026-02-08T19:05:02+11:00" level=trace msg="scheduling prefetch in 125s" Feb 08 19:05:02 audio go-librespot[1563]: time="2026-02-08T19:05:02+11:00" level=trace msg="emitting websocket event: metadata" Feb 08 19:05:02 audio volumio[1210]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2nnDPEbNxnBKq5RG6sObTg","name":"Naal Nachna","artist_names":["Shashwat Sachdev","Afsana Khan","Irshad Kamil","Reble"],"album_name":"Dhurandhar","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02c53e5adf9f81693d62f98019","position":0,"duration":155142,"release_date":"year:2025 month:12 day:5","track_number":10,"disc_number":1}} Feb 08 19:05:02 audio go-librespot[1563]: time="2026-02-08T19:05:02+11:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 08 19:05:02 audio go-librespot[1563]: time="2026-02-08T19:05:02+11:00" level=trace msg="emitting websocket event: playing" Feb 08 19:05:02 audio volumio[1210]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:2nnDPEbNxnBKq5RG6sObTg","uri":"spotify:track:2nnDPEbNxnBKq5RG6sObTg","resume":false,"play_origin":"go-librespot"}} Feb 08 19:05:02 audio volumio[1210]: SPOTIFY: PUSH STATE SPOTIFY Feb 08 19:05:02 audio volumio[1210]: SPOTIFY: {"status":"play","service":"spop","title":"Naal Nachna","artist":"Shashwat Sachdev, Afsana Khan, Irshad Kamil, Reble","album":"Dhurandhar","albumart":"https://i.scdn.co/image/ab67616d00001e02c53e5adf9f81693d62f98019","uri":"spotify:track:2nnDPEbNxnBKq5RG6sObTg","trackType":"spotify","seek":0,"duration":155,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 08 19:05:02 audio volumio[1210]: info: CoreCommandRouter::servicePushState Feb 08 19:05:02 audio volumio[1210]: info: CorePlayQueue::getTrack 12 Feb 08 19:05:02 audio volumio[1210]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Naal Nachna","artist":"Shashwat Sachdev, Afsana Khan, Irshad Kamil, Reble","album":"Dhurandhar","albumart":"https://i.scdn.co/image/ab67616d00001e02c53e5adf9f81693d62f98019","uri":"spotify:track:2nnDPEbNxnBKq5RG6sObTg","trackType":"spotify","seek":0,"duration":155,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 08 19:05:02 audio volumio[1210]: verbose: CURRENT POSITION 12 Feb 08 19:05:02 audio volumio[1210]: info: CoreStateMachine::syncState stateService play Feb 08 19:05:02 audio volumio[1210]: info: CoreStateMachine::syncState currentStatus stop Feb 08 19:05:02 audio volumio[1210]: SPOTIFY: PUSH STATE SPOTIFY Feb 08 19:05:02 audio volumio[1210]: SPOTIFY: {"status":"play","service":"spop","title":"Naal Nachna","artist":"Shashwat Sachdev, Afsana Khan, Irshad Kamil, Reble","album":"Dhurandhar","albumart":"https://i.scdn.co/image/ab67616d00001e02c53e5adf9f81693d62f98019","uri":"spotify:track:2nnDPEbNxnBKq5RG6sObTg","trackType":"spotify","seek":0,"duration":155,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 08 19:05:02 audio volumio[1210]: info: CoreCommandRouter::servicePushState Feb 08 19:05:02 audio volumio[1210]: info: CorePlayQueue::getTrack 12 Feb 08 19:05:02 audio volumio[1210]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Naal Nachna","artist":"Shashwat Sachdev, Afsana Khan, Irshad Kamil, Reble","album":"Dhurandhar","albumart":"https://i.scdn.co/image/ab67616d00001e02c53e5adf9f81693d62f98019","uri":"spotify:track:2nnDPEbNxnBKq5RG6sObTg","trackType":"spotify","seek":0,"duration":155,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 08 19:05:02 audio volumio[1210]: verbose: CURRENT POSITION 12 Feb 08 19:05:02 audio volumio[1210]: info: CoreStateMachine::syncState stateService play Feb 08 19:05:02 audio volumio[1210]: info: CoreStateMachine::syncState currentStatus play Feb 08 19:05:02 audio volumio[1210]: info: Received an update from plugin. extracting info from payload Feb 08 19:05:02 audio volumio[1210]: info: CoreStateMachine::pushState Feb 08 19:05:02 audio volumio[1210]: info: CorePlayQueue::getTrack 12 Feb 08 19:05:02 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 08 19:05:02 audio volumio[1210]: info: CoreCommandRouter::volumioPushState Feb 08 19:05:02 audio volumio[1210]: info: CoreStateMachine::pushState Feb 08 19:05:02 audio volumio[1210]: info: CorePlayQueue::getTrack 12 Feb 08 19:05:02 audio volumio[1210]: info: CoreCommandRouter::volumioPushState Feb 08 19:05:02 audio volumio[1210]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 08 19:05:02 audio volumio[1210]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 08 19:05:11 audio sudo[2803]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 08 19:05:11 audio sudo[2803]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 19:05:11 audio sudo[2803]: pam_unix(sudo:session): session closed for user root Feb 08 19:05:11 audio sudo[2805]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 08 19:05:11 audio sudo[2805]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 19:05:11 audio sudo[2805]: pam_unix(sudo:session): session closed for user root Feb 08 19:05:11 audio volumio[1210]: verbose: New Socket.io Connection to 10.0.0.219 from 10.0.0.206 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: 8 Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::volumioGetVisibleSources Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::volumioGetState Feb 08 19:05:11 audio volumio[1210]: info: CorePlayQueue::getTrack 12 Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 08 19:05:11 audio volumio[1210]: info: Received Get System Info Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 08 19:05:11 audio volumio[1210]: info: Discovery: Getting this device information Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::volumioGetState Feb 08 19:05:11 audio volumio[1210]: info: CorePlayQueue::getTrack 12 Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::volumioGetState Feb 08 19:05:11 audio volumio[1210]: info: CorePlayQueue::getTrack 12 Feb 08 19:05:11 audio volumio[1210]: info: Listing playlists Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs Feb 08 19:05:11 audio volumio[1210]: info: Received Get System Version Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 08 19:05:11 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Feb 08 19:05:13 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Feb 08 19:05:13 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 08 19:05:13 audio volumio[1210]: info: Received Get System Info Feb 08 19:05:13 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 08 19:05:13 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 08 19:05:13 audio volumio[1210]: info: Discovery: Getting this device information Feb 08 19:05:13 audio volumio[1210]: info: CoreCommandRouter::volumioGetState Feb 08 19:05:13 audio volumio[1210]: info: CorePlayQueue::getTrack 12 Feb 08 19:05:13 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 08 19:05:14 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 08 19:05:14 audio volumio[1210]: info: Received Get System Info Feb 08 19:05:14 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 08 19:05:14 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 08 19:05:14 audio volumio[1210]: info: Discovery: Getting this device information Feb 08 19:05:14 audio volumio[1210]: info: CoreCommandRouter::volumioGetState Feb 08 19:05:14 audio volumio[1210]: info: CorePlayQueue::getTrack 12 Feb 08 19:05:14 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 08 19:05:15 audio go-librespot[1563]: time="2026-02-08T19:05:15+11:00" level=debug msg="fetched chunk 4/12, size: 524288" uri="spotify:track:2nnDPEbNxnBKq5RG6sObTg" Feb 08 19:05:17 audio go-librespot[1563]: time="2026-02-08T19:05:17+11:00" level=trace msg="sent dealer ping" Feb 08 19:05:17 audio go-librespot[1563]: time="2026-02-08T19:05:17+11:00" level=trace msg="received dealer pong" Feb 08 19:05:21 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 08 19:05:25 audio volumio[1210]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 08 19:05:25 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Feb 08 19:05:25 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 19:05:25 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Feb 08 19:05:25 audio volumio[1210]: info: Getting Alsa Cards List without I2S DAC Feb 08 19:05:25 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SNumber Feb 08 19:05:25 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 19:05:25 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 08 19:05:25 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 08 19:05:25 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 08 19:05:25 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 08 19:05:25 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 08 19:05:25 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 08 19:05:25 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 08 19:05:25 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Feb 08 19:05:25 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Feb 08 19:05:27 audio go-librespot[1563]: time="2026-02-08T19:05:27+11:00" level=debug msg="fetched chunk 5/12, size: 524288" uri="spotify:track:2nnDPEbNxnBKq5RG6sObTg" Feb 08 19:05:29 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 08 19:05:29 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 08 19:05:30 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 08 19:05:30 audio volumio[1210]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Feb 08 19:05:30 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Feb 08 19:05:30 audio volumio[1210]: info: Received Get System Version Feb 08 19:05:30 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 08 19:05:30 audio volumio[1210]: info: Received Get System Info Feb 08 19:05:30 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 08 19:05:30 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 08 19:05:30 audio volumio[1210]: info: Discovery: Getting this device information Feb 08 19:05:30 audio volumio[1210]: info: CoreCommandRouter::volumioGetState Feb 08 19:05:30 audio volumio[1210]: info: CorePlayQueue::getTrack 12 Feb 08 19:05:30 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 08 19:05:35 audio volumio[1210]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 08 19:05:40 audio go-librespot[1563]: time="2026-02-08T19:05:40+11:00" level=debug msg="fetched chunk 6/12, size: 524288" uri="spotify:track:2nnDPEbNxnBKq5RG6sObTg" Feb 08 19:05:41 audio volumio[1210]: info: [ytmusic] Innertube support service: Deno not installed or otherwise failed to start: Command failed: npx --no-install --yes deno --version Feb 08 19:05:41 audio volumio[1210]: info: [ytmusic] Innertube support service: Start service with Node Feb 08 19:05:44 audio volumio[1210]: info: [ytmusic] Innertube support service: result: {"status":"started","server":{"address":"127.0.0.1","port":37749}} Feb 08 19:05:44 audio volumio[1210]: info: [ytmusic] Innertube support service running at http://127.0.0.1:37749 Feb 08 19:05:47 audio go-librespot[1563]: time="2026-02-08T19:05:47+11:00" level=trace msg="sent dealer ping" Feb 08 19:05:47 audio go-librespot[1563]: time="2026-02-08T19:05:47+11:00" level=trace msg="received dealer pong" Feb 08 19:05:50 audio volumio[1210]: info: [ytmusic] Obtained session PO token using visitorData (expires in 43199 seconds) Feb 08 19:05:53 audio go-librespot[1563]: time="2026-02-08T19:05:53+11:00" level=debug msg="fetched chunk 7/12, size: 524288" uri="spotify:track:2nnDPEbNxnBKq5RG6sObTg" Feb 08 19:05:53 audio volumio[1210]: info: [ytmusic] Going to refresh session PO token in 43099 seconds Feb 08 19:06:05 audio go-librespot[1563]: time="2026-02-08T19:06:05+11:00" level=debug msg="fetched chunk 8/12, size: 524288" uri="spotify:track:2nnDPEbNxnBKq5RG6sObTg" Feb 08 19:06:10 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 08 19:06:10 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 08 19:06:17 audio go-librespot[1563]: time="2026-02-08T19:06:17+11:00" level=trace msg="sent dealer ping" Feb 08 19:06:17 audio go-librespot[1563]: time="2026-02-08T19:06:17+11:00" level=trace msg="received dealer pong" Feb 08 19:06:17 audio go-librespot[1563]: time="2026-02-08T19:06:17+11:00" level=debug msg="fetched chunk 9/12, size: 524288" uri="spotify:track:2nnDPEbNxnBKq5RG6sObTg" Feb 08 19:06:17 audio volumio[1210]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 08 19:06:29 audio go-librespot[1563]: time="2026-02-08T19:06:29+11:00" level=debug msg="fetched chunk 10/12, size: 524288" uri="spotify:track:2nnDPEbNxnBKq5RG6sObTg" Feb 08 19:06:40 audio volumio[1210]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 08 19:06:40 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 08 19:06:40 audio volumio[1210]: info: Creating Spotify config file Feb 08 19:06:40 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 19:06:40 audio volumio[1210]: info: Spotify config file written Feb 08 19:06:40 audio sudo[3057]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 08 19:06:40 audio sudo[3057]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 19:06:40 audio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 08 19:06:40 audio systemd[1]: go-librespot-daemon.service: Killing process 1569 (go-librespot) with signal SIGKILL. Feb 08 19:06:40 audio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 08 19:06:40 audio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 19:06:40 audio systemd[1]: go-librespot-daemon.service: Consumed 3.545s CPU time. Feb 08 19:06:40 audio volumio[1210]: info: Connection to go-librespot Websocket closed Feb 08 19:06:40 audio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 19:06:40 audio go-librespot[3059]: go-librespot daemon starting... Feb 08 19:06:40 audio sudo[3057]: pam_unix(sudo:session): session closed for user root Feb 08 19:06:40 audio go-librespot[3060]: time="2026-02-08T19:06:40+11:00" level=info msg="running go-librespot 0.6.2" Feb 08 19:06:40 audio go-librespot[3060]: time="2026-02-08T19:06:40+11:00" level=debug msg="app state loaded" Feb 08 19:06:40 audio go-librespot[3060]: time="2026-02-08T19:06:40+11:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 19:06:40 audio go-librespot[3060]: time="2026-02-08T19:06:40+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 08 19:06:40 audio go-librespot[3060]: time="2026-02-08T19:06:40+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 08 19:06:40 audio go-librespot[3060]: time="2026-02-08T19:06:40+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 08 19:06:40 audio go-librespot[3060]: time="2026-02-08T19:06:40+11:00" level=info msg="zeroconf server listening on port 44837" Feb 08 19:06:40 audio go-librespot[3060]: time="2026-02-08T19:06:40+11:00" level=debug msg="obtained new client token: AAC2s4rKtSqa5SCmXN6PV0au9VFo0r9UbU9GASELbtqmEio7dizkpEt7HmdmU4h5gHyTgg/n4v4QRnBV81xm2619RDSDCMSBu3lNDC6py3gtLLRXRdgZbhWxPDCZRNaFJCL/B/3t+RfduBZXKomoqX/RG9c8b45YyZ8b/b61Jniy+dVo9eyB7y5q1b2dDF6qlNq2DZqq/itFK8APEz4PfD++MNiZc3M47VojRGzks7LRGEwVJIR75Q==" Feb 08 19:06:41 audio go-librespot[3060]: time="2026-02-08T19:06:41+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Feb 08 19:06:41 audio go-librespot[3060]: time="2026-02-08T19:06:41+11:00" level=debug msg="completed keyexchange" Feb 08 19:06:41 audio go-librespot[3060]: time="2026-02-08T19:06:41+11:00" level=debug msg="completed challenge" Feb 08 19:06:41 audio go-librespot[3060]: time="2026-02-08T19:06:41+11:00" level=info msg="authenticated AP" username="rr**01" Feb 08 19:06:41 audio go-librespot[3060]: time="2026-02-08T19:06:41+11:00" level=info msg="authenticated Login5" username="rr**01" Feb 08 19:06:41 audio go-librespot[3060]: time="2026-02-08T19:06:41+11:00" level=debug msg="initializing zeroconf session" username="rr**01" Feb 08 19:06:41 audio go-librespot[3060]: time="2026-02-08T19:06:41+11:00" level=debug msg="dealer connection opened" Feb 08 19:06:41 audio go-librespot[3060]: time="2026-02-08T19:06:41+11:00" level=trace msg="starting accesspoint recv loop" Feb 08 19:06:41 audio go-librespot[3060]: time="2026-02-08T19:06:41+11:00" level=trace msg="starting dealer recv loop" Feb 08 19:06:41 audio go-librespot[3060]: time="2026-02-08T19:06:41+11:00" level=trace msg="received accesspoint ping" Feb 08 19:06:41 audio go-librespot[3060]: time="2026-02-08T19:06:41+11:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 08 19:06:41 audio go-librespot[3060]: time="2026-02-08T19:06:41+11:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 08 19:06:41 audio go-librespot[3060]: time="2026-02-08T19:06:41+11:00" level=debug msg="received connection id: ZWRlYmJhMjgtMTdl...OTNFRjRCNzJDRA==" Feb 08 19:06:42 audio go-librespot[3060]: time="2026-02-08T19:06:42+11:00" level=debug msg="put connect state because NEW_DEVICE" Feb 08 19:06:42 audio go-librespot[3060]: time="2026-02-08T19:06:42+11:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 08 19:06:42 audio go-librespot[3060]: time="2026-02-08T19:06:42+11:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 08 19:06:42 audio go-librespot[3060]: time="2026-02-08T19:06:42+11:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 08 19:06:42 audio go-librespot[3060]: time="2026-02-08T19:06:42+11:00" level=trace msg="received accesspoint pong ack" Feb 08 19:06:43 audio volumio[1210]: info: Initializing connection to go-librespot Websocket Feb 08 19:06:43 audio go-librespot[3060]: time="2026-02-08T19:06:43+11:00" level=debug msg="new websocket client" Feb 08 19:06:43 audio volumio[1210]: info: Connection to go-librespot Websocket established Feb 08 19:06:43 audio volumio[1210]: info: go-librespot daemon successfully initialized Feb 08 19:06:44 audio volumio[1210]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 08 19:06:44 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 08 19:06:44 audio volumio[1210]: info: Creating Spotify config file Feb 08 19:06:44 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 19:06:44 audio volumio[1210]: info: Spotify config file written Feb 08 19:06:44 audio sudo[3089]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 08 19:06:44 audio sudo[3089]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 19:06:44 audio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 08 19:06:44 audio systemd[1]: go-librespot-daemon.service: Killing process 3068 (go-librespot) with signal SIGKILL. Feb 08 19:06:44 audio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 08 19:06:44 audio volumio[1210]: info: Connection to go-librespot Websocket closed Feb 08 19:06:44 audio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 19:06:44 audio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 19:06:44 audio go-librespot[3091]: go-librespot daemon starting... Feb 08 19:06:44 audio sudo[3089]: pam_unix(sudo:session): session closed for user root Feb 08 19:06:44 audio go-librespot[3092]: time="2026-02-08T19:06:44+11:00" level=info msg="running go-librespot 0.6.2" Feb 08 19:06:44 audio go-librespot[3092]: time="2026-02-08T19:06:44+11:00" level=debug msg="app state loaded" Feb 08 19:06:44 audio go-librespot[3092]: time="2026-02-08T19:06:44+11:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 19:06:44 audio go-librespot[3092]: time="2026-02-08T19:06:44+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 08 19:06:44 audio go-librespot[3092]: time="2026-02-08T19:06:44+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 08 19:06:44 audio go-librespot[3092]: time="2026-02-08T19:06:44+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 08 19:06:44 audio go-librespot[3092]: time="2026-02-08T19:06:44+11:00" level=info msg="zeroconf server listening on port 34201" Feb 08 19:06:44 audio go-librespot[3092]: time="2026-02-08T19:06:44+11:00" level=debug msg="obtained new client token: AABreDXZZcHOl5dboKLKH/HrpwJaS6ha6SNsdTwz607gV+wCF8YHJMDbEyqVOqus4BH/62AThRxIyda2oWgMtODgZn9Q1tr+kK0n3d8a2nKtxPhR72V+MAK8sVyzv9WJzMP/v2UhR0h/FDd20k999s2RKKPAsjHw01oXTomQQcd56TeplwrDdl1ylcsGJCOR/bvVFO4l1yOmF0rkph3FLeHXLJkX2+N11IWbnFPc6gcL1m4VOXlo0A==" Feb 08 19:06:45 audio go-librespot[3092]: time="2026-02-08T19:06:45+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Feb 08 19:06:45 audio go-librespot[3092]: time="2026-02-08T19:06:45+11:00" level=debug msg="completed keyexchange" Feb 08 19:06:45 audio go-librespot[3092]: time="2026-02-08T19:06:45+11:00" level=debug msg="completed challenge" Feb 08 19:06:45 audio go-librespot[3092]: time="2026-02-08T19:06:45+11:00" level=info msg="authenticated AP" username="rr**01" Feb 08 19:06:45 audio go-librespot[3092]: time="2026-02-08T19:06:45+11:00" level=info msg="authenticated Login5" username="rr**01" Feb 08 19:06:45 audio go-librespot[3092]: time="2026-02-08T19:06:45+11:00" level=debug msg="initializing zeroconf session" username="rr**01" Feb 08 19:06:45 audio go-librespot[3092]: time="2026-02-08T19:06:45+11:00" level=debug msg="dealer connection opened" Feb 08 19:06:45 audio go-librespot[3092]: time="2026-02-08T19:06:45+11:00" level=trace msg="starting accesspoint recv loop" Feb 08 19:06:45 audio go-librespot[3092]: time="2026-02-08T19:06:45+11:00" level=trace msg="starting dealer recv loop" Feb 08 19:06:45 audio go-librespot[3092]: time="2026-02-08T19:06:45+11:00" level=trace msg="received accesspoint ping" Feb 08 19:06:45 audio go-librespot[3092]: time="2026-02-08T19:06:45+11:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 08 19:06:45 audio go-librespot[3092]: time="2026-02-08T19:06:45+11:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 08 19:06:45 audio go-librespot[3092]: time="2026-02-08T19:06:45+11:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 08 19:06:45 audio go-librespot[3092]: time="2026-02-08T19:06:45+11:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 08 19:06:45 audio go-librespot[3092]: time="2026-02-08T19:06:45+11:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 08 19:06:45 audio go-librespot[3092]: time="2026-02-08T19:06:45+11:00" level=debug msg="received connection id: MzZkYWE1MjAtOTE0...ODFGRDhDNTE2MA==" Feb 08 19:06:46 audio go-librespot[3092]: time="2026-02-08T19:06:46+11:00" level=trace msg="received accesspoint pong ack" Feb 08 19:06:46 audio go-librespot[3092]: time="2026-02-08T19:06:46+11:00" level=debug msg="put connect state because NEW_DEVICE" Feb 08 19:06:46 audio volumio[1210]: info: Getting Spotify volume Feb 08 19:06:46 audio volumio[1210]: info: Spotify volume: 100 Feb 08 19:06:46 audio volumio[1210]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Feb 08 19:06:46 audio volumio[1210]: info: Initializing connection to go-librespot Websocket Feb 08 19:06:46 audio volumio[1210]: info: CoreCommandRouter::volumioGetState Feb 08 19:06:46 audio go-librespot[3092]: time="2026-02-08T19:06:46+11:00" level=debug msg="new websocket client" Feb 08 19:06:46 audio volumio[1210]: info: CorePlayQueue::getTrack 12 Feb 08 19:06:46 audio volumio[1210]: info: Connection to go-librespot Websocket established Feb 08 19:06:46 audio volumio[1210]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 08 19:06:47 audio volumio[1210]: info: Initializing connection to go-librespot Websocket Feb 08 19:06:47 audio go-librespot[3092]: time="2026-02-08T19:06:47+11:00" level=debug msg="new websocket client" Feb 08 19:06:47 audio volumio[1210]: info: Connection to go-librespot Websocket established Feb 08 19:06:47 audio volumio[1210]: info: go-librespot daemon successfully initialized Feb 08 19:06:48 audio volumio[1210]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 08 19:06:48 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 08 19:06:48 audio volumio[1210]: info: Creating Spotify config file Feb 08 19:06:48 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 19:06:48 audio volumio[1210]: info: Spotify config file written Feb 08 19:06:48 audio sudo[3102]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 08 19:06:48 audio sudo[3102]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 19:06:48 audio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 08 19:06:48 audio volumio[1210]: info: Connection to go-librespot Websocket closed Feb 08 19:06:48 audio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 08 19:06:48 audio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 19:06:48 audio volumio[1210]: info: Connection to go-librespot Websocket closed Feb 08 19:06:48 audio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 19:06:48 audio go-librespot[3104]: go-librespot daemon starting... Feb 08 19:06:48 audio sudo[3102]: pam_unix(sudo:session): session closed for user root Feb 08 19:06:48 audio go-librespot[3105]: time="2026-02-08T19:06:48+11:00" level=info msg="running go-librespot 0.6.2" Feb 08 19:06:48 audio go-librespot[3105]: time="2026-02-08T19:06:48+11:00" level=debug msg="app state loaded" Feb 08 19:06:48 audio go-librespot[3105]: time="2026-02-08T19:06:48+11:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 19:06:48 audio go-librespot[3105]: time="2026-02-08T19:06:48+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 08 19:06:48 audio go-librespot[3105]: time="2026-02-08T19:06:48+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 08 19:06:48 audio go-librespot[3105]: time="2026-02-08T19:06:48+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 08 19:06:48 audio go-librespot[3105]: time="2026-02-08T19:06:48+11:00" level=info msg="zeroconf server listening on port 38425" Feb 08 19:06:49 audio go-librespot[3105]: time="2026-02-08T19:06:49+11:00" level=debug msg="obtained new client token: AACYpofy+3WVmBRtiyg/Tds6dILxpDdxJ1xNnPjVmx/gzVJOl13LFtKwfb/wjVeq1vPOPuBO8Jpg9uYrQuTq7ZcwMj+Ts9kOOs1qUFhsyahprV9xB8c5K2yOa4JrZS4soyXXcJFdFtKKGJz17RBtaTBKASFo3VA9bai9y10gOxysFc0VddNVD44odabduGRnyzJU/SDM70s2FGoEPSqOUAy1U+tkJEjVnLjMaTuKHXlgW7hzEjY=" Feb 08 19:06:49 audio go-librespot[3105]: time="2026-02-08T19:06:49+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Feb 08 19:06:49 audio volumio[1210]: info: Getting Spotify volume Feb 08 19:06:49 audio volumio[1210]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Feb 08 19:06:49 audio volumio[1210]: info: CoreCommandRouter::volumioGetState Feb 08 19:06:49 audio volumio[1210]: info: CorePlayQueue::getTrack 12 Feb 08 19:06:49 audio volumio[1210]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 08 19:06:49 audio go-librespot[3105]: time="2026-02-08T19:06:49+11:00" level=debug msg="completed keyexchange" Feb 08 19:06:49 audio go-librespot[3105]: time="2026-02-08T19:06:49+11:00" level=debug msg="completed challenge" Feb 08 19:06:49 audio go-librespot[3105]: time="2026-02-08T19:06:49+11:00" level=info msg="authenticated AP" username="rr**01" Feb 08 19:06:49 audio go-librespot[3105]: time="2026-02-08T19:06:49+11:00" level=info msg="authenticated Login5" username="rr**01" Feb 08 19:06:49 audio go-librespot[3105]: time="2026-02-08T19:06:49+11:00" level=debug msg="initializing zeroconf session" username="rr**01" Feb 08 19:06:50 audio go-librespot[3105]: time="2026-02-08T19:06:50+11:00" level=debug msg="dealer connection opened" Feb 08 19:06:50 audio go-librespot[3105]: time="2026-02-08T19:06:50+11:00" level=trace msg="starting accesspoint recv loop" Feb 08 19:06:50 audio go-librespot[3105]: time="2026-02-08T19:06:50+11:00" level=trace msg="starting dealer recv loop" Feb 08 19:06:50 audio go-librespot[3105]: time="2026-02-08T19:06:50+11:00" level=trace msg="received accesspoint ping" Feb 08 19:06:50 audio go-librespot[3105]: time="2026-02-08T19:06:50+11:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 08 19:06:50 audio go-librespot[3105]: time="2026-02-08T19:06:50+11:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 08 19:06:50 audio go-librespot[3105]: time="2026-02-08T19:06:50+11:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 08 19:06:50 audio go-librespot[3105]: time="2026-02-08T19:06:50+11:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 08 19:06:50 audio go-librespot[3105]: time="2026-02-08T19:06:50+11:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 08 19:06:50 audio go-librespot[3105]: time="2026-02-08T19:06:50+11:00" level=debug msg="received connection id: MGI5MmRlNGMtMzgz...ODVGN0VCNzE1MQ==" Feb 08 19:06:50 audio volumio[1210]: info: Spotify volume: 100 Feb 08 19:06:50 audio go-librespot[3105]: time="2026-02-08T19:06:50+11:00" level=trace msg="received accesspoint pong ack" Feb 08 19:06:50 audio go-librespot[3105]: time="2026-02-08T19:06:50+11:00" level=debug msg="put connect state because NEW_DEVICE" Feb 08 19:06:50 audio volumio[1210]: info: Getting Spotify volume Feb 08 19:06:50 audio volumio[1210]: info: Spotify volume: 100 Feb 08 19:06:50 audio volumio[1210]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Feb 08 19:06:50 audio volumio[1210]: info: CoreCommandRouter::volumioGetState Feb 08 19:06:50 audio volumio[1210]: info: CorePlayQueue::getTrack 12 Feb 08 19:06:50 audio volumio[1210]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 08 19:06:50 audio volumio[1210]: info: Initializing connection to go-librespot Websocket Feb 08 19:06:50 audio go-librespot[3105]: time="2026-02-08T19:06:50+11:00" level=debug msg="new websocket client" Feb 08 19:06:50 audio volumio[1210]: info: Connection to go-librespot Websocket established Feb 08 19:06:51 audio volumio[1210]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 08 19:06:51 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 08 19:06:51 audio volumio[1210]: info: Creating Spotify config file Feb 08 19:06:51 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 19:06:51 audio volumio[1210]: info: Spotify config file written Feb 08 19:06:51 audio sudo[3129]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 08 19:06:51 audio sudo[3129]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 19:06:51 audio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 08 19:06:51 audio systemd[1]: go-librespot-daemon.service: Killing process 3109 (go-librespot) with signal SIGKILL. Feb 08 19:06:51 audio volumio[1210]: info: Connection to go-librespot Websocket closed Feb 08 19:06:51 audio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 08 19:06:51 audio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 19:06:51 audio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 19:06:51 audio go-librespot[3131]: go-librespot daemon starting... Feb 08 19:06:51 audio sudo[3129]: pam_unix(sudo:session): session closed for user root Feb 08 19:06:51 audio go-librespot[3132]: time="2026-02-08T19:06:51+11:00" level=info msg="running go-librespot 0.6.2" Feb 08 19:06:51 audio go-librespot[3132]: time="2026-02-08T19:06:51+11:00" level=debug msg="app state loaded" Feb 08 19:06:51 audio go-librespot[3132]: time="2026-02-08T19:06:51+11:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 19:06:51 audio go-librespot[3132]: time="2026-02-08T19:06:51+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 08 19:06:51 audio go-librespot[3132]: time="2026-02-08T19:06:51+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 08 19:06:51 audio go-librespot[3132]: time="2026-02-08T19:06:51+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 08 19:06:51 audio go-librespot[3132]: time="2026-02-08T19:06:51+11:00" level=info msg="zeroconf server listening on port 43207" Feb 08 19:06:51 audio volumio[1210]: info: go-librespot daemon successfully initialized Feb 08 19:06:51 audio go-librespot[3132]: time="2026-02-08T19:06:51+11:00" level=debug msg="obtained new client token: AAB13cGTJSYPSYAQ8eLPsEq+GpGmijOSPZ3WKV1M6cXnKvIvNKA151f/GZ7lURGcDp/oBNcYXeKCLAxN0vTjQ0dutvmafWT/b3mc2Q50KpCA16vEIrbp/rJI3T1m3ed7eSdlyntUsaqu4rFE1V0C+beFCOnJ+Cl65vOJr+67nR+1OikGRHfarW3VPk3rMHMAf3GIXCbZKrkgjXtmnH4vCNFCP2QNynzI4SNytgYhpBfUTipTh705hA==" Feb 08 19:06:51 audio go-librespot[3132]: time="2026-02-08T19:06:51+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Feb 08 19:06:52 audio go-librespot[3132]: time="2026-02-08T19:06:52+11:00" level=debug msg="completed keyexchange" Feb 08 19:06:52 audio go-librespot[3132]: time="2026-02-08T19:06:52+11:00" level=debug msg="completed challenge" Feb 08 19:06:52 audio go-librespot[3132]: time="2026-02-08T19:06:52+11:00" level=info msg="authenticated AP" username="rr**01" Feb 08 19:06:52 audio go-librespot[3132]: time="2026-02-08T19:06:52+11:00" level=info msg="authenticated Login5" username="rr**01" Feb 08 19:06:52 audio go-librespot[3132]: time="2026-02-08T19:06:52+11:00" level=debug msg="initializing zeroconf session" username="rr**01" Feb 08 19:06:52 audio go-librespot[3132]: time="2026-02-08T19:06:52+11:00" level=debug msg="dealer connection opened" Feb 08 19:06:52 audio go-librespot[3132]: time="2026-02-08T19:06:52+11:00" level=trace msg="starting accesspoint recv loop" Feb 08 19:06:52 audio go-librespot[3132]: time="2026-02-08T19:06:52+11:00" level=trace msg="received accesspoint ping" Feb 08 19:06:52 audio go-librespot[3132]: time="2026-02-08T19:06:52+11:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 08 19:06:52 audio go-librespot[3132]: time="2026-02-08T19:06:52+11:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 08 19:06:52 audio go-librespot[3132]: time="2026-02-08T19:06:52+11:00" level=trace msg="starting dealer recv loop" Feb 08 19:06:52 audio go-librespot[3132]: time="2026-02-08T19:06:52+11:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 08 19:06:52 audio go-librespot[3132]: time="2026-02-08T19:06:52+11:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 08 19:06:52 audio go-librespot[3132]: time="2026-02-08T19:06:52+11:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 08 19:06:52 audio go-librespot[3132]: time="2026-02-08T19:06:52+11:00" level=debug msg="received connection id: NGMxODY4ZjQtNzQ0...NkYyQTNBRURDMg==" Feb 08 19:06:52 audio go-librespot[3132]: time="2026-02-08T19:06:52+11:00" level=trace msg="received accesspoint pong ack" Feb 08 19:06:52 audio go-librespot[3132]: time="2026-02-08T19:06:52+11:00" level=debug msg="put connect state because NEW_DEVICE" Feb 08 19:06:53 audio volumio[1210]: info: Getting Spotify volume Feb 08 19:06:53 audio volumio[1210]: info: Spotify volume: 100 Feb 08 19:06:53 audio volumio[1210]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Feb 08 19:06:53 audio volumio[1210]: info: CoreCommandRouter::volumioGetState Feb 08 19:06:53 audio volumio[1210]: info: CorePlayQueue::getTrack 12 Feb 08 19:06:53 audio volumio[1210]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 08 19:06:54 audio volumio[1210]: info: Initializing connection to go-librespot Websocket Feb 08 19:06:54 audio go-librespot[3132]: time="2026-02-08T19:06:54+11:00" level=debug msg="new websocket client" Feb 08 19:06:54 audio volumio[1210]: info: Connection to go-librespot Websocket established Feb 08 19:06:54 audio volumio[1210]: info: go-librespot daemon successfully initialized Feb 08 19:06:54 audio volumio[1210]: info: Initializing connection to go-librespot Websocket Feb 08 19:06:54 audio go-librespot[3132]: time="2026-02-08T19:06:54+11:00" level=debug msg="new websocket client" Feb 08 19:06:54 audio volumio[1210]: info: Connection to go-librespot Websocket established Feb 08 19:06:56 audio volumio[1210]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 08 19:06:56 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 08 19:06:56 audio volumio[1210]: info: Creating Spotify config file Feb 08 19:06:56 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 19:06:56 audio volumio[1210]: info: Spotify config file written Feb 08 19:06:56 audio sudo[3150]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 08 19:06:56 audio sudo[3150]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 19:06:56 audio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 08 19:06:56 audio systemd[1]: go-librespot-daemon.service: Killing process 3136 (go-librespot) with signal SIGKILL. Feb 08 19:06:56 audio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 08 19:06:56 audio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 19:06:56 audio volumio[1210]: info: Connection to go-librespot Websocket closed Feb 08 19:06:56 audio volumio[1210]: info: Connection to go-librespot Websocket closed Feb 08 19:06:56 audio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 19:06:56 audio go-librespot[3152]: go-librespot daemon starting... Feb 08 19:06:56 audio sudo[3150]: pam_unix(sudo:session): session closed for user root Feb 08 19:06:56 audio go-librespot[3153]: time="2026-02-08T19:06:56+11:00" level=info msg="running go-librespot 0.6.2" Feb 08 19:06:56 audio go-librespot[3153]: time="2026-02-08T19:06:56+11:00" level=debug msg="app state loaded" Feb 08 19:06:57 audio go-librespot[3153]: time="2026-02-08T19:06:57+11:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 19:06:57 audio volumio[1210]: info: Getting Spotify volume Feb 08 19:06:57 audio volumio[1210]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Feb 08 19:06:57 audio volumio[1210]: info: CoreCommandRouter::volumioGetState Feb 08 19:06:57 audio volumio[1210]: info: CorePlayQueue::getTrack 12 Feb 08 19:06:57 audio volumio[1210]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 08 19:06:57 audio go-librespot[3153]: time="2026-02-08T19:06:57+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 08 19:06:57 audio go-librespot[3153]: time="2026-02-08T19:06:57+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 08 19:06:57 audio go-librespot[3153]: time="2026-02-08T19:06:57+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 08 19:06:57 audio go-librespot[3153]: time="2026-02-08T19:06:57+11:00" level=info msg="zeroconf server listening on port 37155" Feb 08 19:06:57 audio volumio[1210]: info: Initializing connection to go-librespot Websocket Feb 08 19:06:57 audio go-librespot[3153]: time="2026-02-08T19:06:57+11:00" level=debug msg="new websocket client" Feb 08 19:06:57 audio volumio[1210]: info: Connection to go-librespot Websocket established Feb 08 19:06:57 audio go-librespot[3153]: time="2026-02-08T19:06:57+11:00" level=debug msg="obtained new client token: AADcrqz7jCdXJ8a2jWWNJz2/2CheViTLQRCQEyTLfcXJ0VoLlpe3jwH8YmOS+49kvH+nZ15W/DmPJGD1ZDcZoyC7A6BBG7DjQh9SyF3s4059f+M+JxYSaL7t+uf2g6cj2pfMJl+OTRSx1VOIll7MaB1NiNUlNiRn7ROyUoSC6+uYL/xY/Q/GjLabXowmAmnCL+BQ0KyvuYqL7vsXdWC/tKMe41G4dWan7L90paWCwIF3sNMpA5Rnng==" Feb 08 19:06:57 audio go-librespot[3153]: time="2026-02-08T19:06:57+11:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Feb 08 19:06:57 audio volumio[1210]: info: Getting Spotify volume Feb 08 19:06:57 audio volumio[1210]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Feb 08 19:06:57 audio volumio[1210]: info: CoreCommandRouter::volumioGetState Feb 08 19:06:57 audio volumio[1210]: info: CorePlayQueue::getTrack 12 Feb 08 19:06:57 audio volumio[1210]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 08 19:06:57 audio go-librespot[3153]: time="2026-02-08T19:06:57+11:00" level=debug msg="completed keyexchange" Feb 08 19:06:57 audio go-librespot[3153]: time="2026-02-08T19:06:57+11:00" level=debug msg="completed challenge" Feb 08 19:06:57 audio volumio[1210]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 08 19:06:57 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 08 19:06:57 audio volumio[1210]: info: Creating Spotify config file Feb 08 19:06:57 audio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 19:06:57 audio volumio[1210]: info: Spotify config file written Feb 08 19:06:57 audio sudo[3163]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 08 19:06:57 audio sudo[3163]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 19:06:57 audio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 08 19:06:57 audio systemd[1]: go-librespot-daemon.service: Killing process 3157 (go-librespot) with signal SIGKILL. Feb 08 19:06:57 audio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 08 19:06:57 audio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 19:06:57 audio volumio[1210]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 08 19:06:57 audio volumio[1210]: Error: socket hang up Feb 08 19:06:57 audio volumio[1210]: at connResetException (node:internal/errors:720:14) Feb 08 19:06:57 audio volumio[1210]: at Socket.socketOnEnd (node:_http_client:519:23) Feb 08 19:06:57 audio volumio[1210]: at Socket.emit (node:events:526:35) Feb 08 19:06:57 audio volumio[1210]: at endReadableNT (node:internal/streams/readable:1376:12) Feb 08 19:06:57 audio volumio[1210]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Feb 08 19:06:57 audio volumio[1210]: code: 'ECONNRESET', Feb 08 19:06:57 audio volumio[1210]: response: undefined Feb 08 19:06:57 audio volumio[1210]: } Feb 08 19:06:57 audio volumio[1210]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 08 19:06:57 audio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 19:06:57 audio go-librespot[3165]: go-librespot daemon starting... Feb 08 19:06:57 audio sudo[3163]: pam_unix(sudo:session): session closed for user root Feb 08 19:06:57 audio go-librespot[3177]: time="2026-02-08T19:06:57+11:00" level=info msg="running go-librespot 0.6.2" Feb 08 19:06:57 audio go-librespot[3177]: time="2026-02-08T19:06:57+11:00" level=debug msg="app state loaded" Feb 08 19:06:57 audio go-librespot[3177]: time="2026-02-08T19:06:57+11:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 19:06:58 audio go-librespot[3177]: time="2026-02-08T19:06:58+11:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 08 19:06:58 audio go-librespot[3177]: time="2026-02-08T19:06:58+11:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 08 19:06:58 audio go-librespot[3177]: time="2026-02-08T19:06:58+11:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 08 19:06:58 audio go-librespot[3177]: time="2026-02-08T19:06:58+11:00" level=info msg="zeroconf server listening on port 41029" Feb 08 19:06:58 audio sudo[3189]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-08 19:05' Feb 08 19:06:58 audio sudo[3189]: 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"