-- Logs begin at Thu 2025-07-17 11:26:55 CEST, end at Thu 2025-07-17 11:45:40 CEST. -- Jul 17 11:44:05 volumio go-librespot[3036]: time="2025-07-17T11:44:05+02:00" level=debug msg="fetched chunk 17/22, size: 524288" uri="spotify:track:1yBApD3yKldLpUdsWAWnvS" Jul 17 11:44:16 volumio go-librespot[3036]: time="2025-07-17T11:44:16+02:00" level=debug msg="fetched chunk 18/22, size: 524288" uri="spotify:track:1yBApD3yKldLpUdsWAWnvS" Jul 17 11:44:23 volumio volumio[849]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatest/ferrum_streaming_control_technology/volumio/buster/armhf Jul 17 11:44:25 volumio volumio[849]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatest/ferrum_streaming_control_technology/volumio/buster/armhf Jul 17 11:44:25 volumio volumio[849]: info: FSCT Stopped Jul 17 11:44:25 volumio volumio[849]: info: Check plugin dependencies Jul 17 11:44:25 volumio volumio[849]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 17 11:44:25 volumio volumio[849]: info: Rename folder Jul 17 11:44:25 volumio volumio[849]: info: Folder /tmp/downloaded_plugin.zip removed Jul 17 11:44:25 volumio volumio[849]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 17 11:44:25 volumio volumio[849]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 17 11:44:25 volumio volumio[849]: info: Discovery: Getting this device information Jul 17 11:44:25 volumio volumio[849]: info: CoreCommandRouter::volumioGetState Jul 17 11:44:25 volumio volumio[849]: info: CorePlayQueue::getTrack 3 Jul 17 11:44:25 volumio volumio[849]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 17 11:44:25 volumio volumio[849]: info: Move to category Jul 17 11:44:26 volumio volumio[849]: info: Checking if install.sh is present Jul 17 11:44:26 volumio volumio[849]: info: Executing install.sh Jul 17 11:44:26 volumio sudo[3561]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/user_interface/ferrum_streaming_control_technology/install.sh Jul 17 11:44:26 volumio sudo[3561]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 17 11:44:26 volumio sudo[3561]: pam_unix(sudo:session): session closed for user root Jul 17 11:44:26 volumio go-librespot[3036]: time="2025-07-17T11:44:26+02:00" level=trace msg="sent dealer ping" Jul 17 11:44:26 volumio volumio[849]: info: Install script completed Jul 17 11:44:26 volumio volumio[849]: info: Done installing plugin. Jul 17 11:44:26 volumio volumio[849]: info: Enabling plugin ferrum_streaming_control_technology Jul 17 11:44:26 volumio volumio[849]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jul 17 11:44:26 volumio volumio[849]: info: [{"prettyName":"Spotify","name":"spop","category":"music_service","version":"4.1.4","icon":"fa-spotify","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Amplifier Switch","name":"ampswitch","category":"system_controller","version":"0.2.1","icon":"fa-power-off","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Ferrum Streaming Control Technology","name":"ferrum_streaming_control_technology","category":"user_interface","version":"1.0.1","icon":"fa-play","isManuallyInstalled":false,"enabled":true,"active":false}] Jul 17 11:44:26 volumio volumio[849]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jul 17 11:44:26 volumio volumio[849]: info: Installing ferrum streaming control technology Dependencies Jul 17 11:44:26 volumio go-librespot[3036]: time="2025-07-17T11:44:26+02:00" level=trace msg="received dealer pong" Jul 17 11:44:26 volumio volumio[849]: Plugin install end detected on script Jul 17 11:44:26 volumio volumio[849]: info: Folder /tmp/plugins removed Jul 17 11:44:26 volumio volumio[849]: info: Folder /tmp/downloaded_plugin.zip removed Jul 17 11:44:26 volumio volumio[849]: info: Folder /data/temp removed Jul 17 11:44:28 volumio go-librespot[3036]: time="2025-07-17T11:44:28+02:00" level=debug msg="fetched chunk 19/22, size: 524288" uri="spotify:track:1yBApD3yKldLpUdsWAWnvS" Jul 17 11:44:40 volumio go-librespot[3036]: time="2025-07-17T11:44:40+02:00" level=debug msg="fetched chunk 20/22, size: 524288" uri="spotify:track:1yBApD3yKldLpUdsWAWnvS" Jul 17 11:44:42 volumio volumio[849]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 17 11:44:51 volumio go-librespot[3036]: time="2025-07-17T11:44:51+02:00" level=debug msg="fetched chunk 21/22, size: 524288" uri="spotify:track:1yBApD3yKldLpUdsWAWnvS" Jul 17 11:44:55 volumio volumio[849]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 17 11:44:55 volumio volumio[849]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 17 11:44:55 volumio volumio[849]: info: Discovery: Getting this device information Jul 17 11:44:55 volumio volumio[849]: info: CoreCommandRouter::volumioGetState Jul 17 11:44:55 volumio volumio[849]: info: CorePlayQueue::getTrack 3 Jul 17 11:44:55 volumio volumio[849]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 17 11:44:55 volumio go-librespot[3036]: time="2025-07-17T11:44:55+02:00" level=trace msg="received accesspoint ping" Jul 17 11:44:56 volumio go-librespot[3036]: time="2025-07-17T11:44:56+02:00" level=trace msg="received accesspoint pong ack" Jul 17 11:44:56 volumio go-librespot[3036]: time="2025-07-17T11:44:56+02:00" level=trace msg="sent dealer ping" Jul 17 11:44:56 volumio go-librespot[3036]: time="2025-07-17T11:44:56+02:00" level=trace msg="received dealer pong" Jul 17 11:45:03 volumio go-librespot[3036]: time="2025-07-17T11:45:03+02:00" level=debug msg="fetched chunk 22/22, size: 2436" uri="spotify:track:1yBApD3yKldLpUdsWAWnvS" Jul 17 11:45:04 volumio ntpd[822]: 213.165.71.32 local addr 192.168.1.48 -> Jul 17 11:45:26 volumio go-librespot[3036]: time="2025-07-17T11:45:26+02:00" level=trace msg="sent dealer ping" Jul 17 11:45:26 volumio go-librespot[3036]: time="2025-07-17T11:45:26+02:00" level=trace msg="received dealer pong" Jul 17 11:45:36 volumio volumio[849]: info: CorePlayQueue::getTrack 3 Jul 17 11:45:36 volumio volumio[849]: info: CorePlayQueue::getTrack 287 Jul 17 11:45:36 volumio volumio[849]: info: Prefetching next song Jul 17 11:45:36 volumio volumio[849]: info: [1752745536149] ControllerSpotify::prefetch Jul 17 11:45:36 volumio volumio[849]: info: Sending Spotify command with payload to local API: /player/add_to_queue Jul 17 11:45:36 volumio go-librespot[3036]: time="2025-07-17T11:45:36+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 17 11:45:36 volumio go-librespot[3036]: time="2025-07-17T11:45:36+02:00" level=debug msg="prefetching next track" uri="spotify:track:3xMQOd1C3TXsjQ3pmzOmkC" Jul 17 11:45:36 volumio go-librespot[3036]: time="2025-07-17T11:45:36+02:00" level=debug msg="selected format OGG_VORBIS_320 (7b9d36c60998cbcad4590b8cdb0af32f4363236c)" uri="spotify:track:3xMQOd1C3TXsjQ3pmzOmkC" Jul 17 11:45:36 volumio go-librespot[3036]: time="2025-07-17T11:45:36+02:00" level=debug msg="requested aes key for file 7b9d36c60998cbcad4590b8cdb0af32f4363236c, gid: 3xMQOd1C3TXsjQ3pmzOmkC" Jul 17 11:45:36 volumio go-librespot[3036]: time="2025-07-17T11:45:36+02:00" level=debug msg="fetched first chunk of 31, total size is 16158180 bytes" uri="spotify:track:3xMQOd1C3TXsjQ3pmzOmkC" Jul 17 11:45:36 volumio go-librespot[3036]: time="2025-07-17T11:45:36+02:00" level=info msg="prefetched track \"Weight of Love\" (duration: 410186ms)" uri="spotify:track:3xMQOd1C3TXsjQ3pmzOmkC" Jul 17 11:45:36 volumio go-librespot[3036]: time="2025-07-17T11:45:36+02:00" level=debug msg="fetched chunk 2/30, size: 524288" uri="spotify:track:3xMQOd1C3TXsjQ3pmzOmkC" Jul 17 11:45:36 volumio go-librespot[3036]: time="2025-07-17T11:45:36+02:00" level=debug msg="fetched chunk 1/30, size: 524288" uri="spotify:track:3xMQOd1C3TXsjQ3pmzOmkC" Jul 17 11:45:36 volumio go-librespot[3036]: time="2025-07-17T11:45:36+02:00" level=debug msg="fetched chunk 3/30, size: 524288" uri="spotify:track:3xMQOd1C3TXsjQ3pmzOmkC" Jul 17 11:45:39 volumio go-librespot[3036]: time="2025-07-17T11:45:39+02:00" level=trace msg="emitting websocket event: not_playing" Jul 17 11:45:39 volumio go-librespot[3036]: time="2025-07-17T11:45:39+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3xMQOd1C3TXsjQ3pmzOmkC" Jul 17 11:45:39 volumio volumio[849]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:1yBApD3yKldLpUdsWAWnvS","play_origin":"go-librespot"}} Jul 17 11:45:39 volumio volumio[849]: error: Failed to decode event: not_playing Jul 17 11:45:39 volumio volumio[849]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:1yBApD3yKldLpUdsWAWnvS","play_origin":"go-librespot"}} Jul 17 11:45:39 volumio volumio[849]: error: Failed to decode event: not_playing Jul 17 11:45:39 volumio go-librespot[3036]: time="2025-07-17T11:45:39+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 17 11:45:39 volumio go-librespot[3036]: time="2025-07-17T11:45:39+02:00" level=trace msg="emitting websocket event: will_play" Jul 17 11:45:39 volumio go-librespot[3036]: time="2025-07-17T11:45:39+02:00" level=info msg="loaded track \"Weight of Love\" (paused: false, position: 0ms, duration: 410186ms, prefetched: true)" uri="spotify:track:3xMQOd1C3TXsjQ3pmzOmkC" Jul 17 11:45:39 volumio volumio[849]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3xMQOd1C3TXsjQ3pmzOmkC","play_origin":"go-librespot"}} Jul 17 11:45:39 volumio volumio[849]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3xMQOd1C3TXsjQ3pmzOmkC","play_origin":"go-librespot"}} Jul 17 11:45:39 volumio go-librespot[3036]: time="2025-07-17T11:45:39+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 17 11:45:39 volumio go-librespot[3036]: time="2025-07-17T11:45:39+02:00" level=trace msg="scheduling prefetch in 381s" Jul 17 11:45:39 volumio go-librespot[3036]: time="2025-07-17T11:45:39+02:00" level=trace msg="emitting websocket event: metadata" Jul 17 11:45:39 volumio volumio[849]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3xMQOd1C3TXsjQ3pmzOmkC","name":"Weight of Love","artist_names":["The Black Keys"],"album_name":"Turn Blue","album_cover_url":"https://i.scdn.co/image/ab67616d00001e021af8fb0d8859055d35d2290f","position":0,"duration":410186,"release_date":"year:2014 month:5 day:9","track_number":1,"disc_number":1}} Jul 17 11:45:39 volumio volumio[849]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3xMQOd1C3TXsjQ3pmzOmkC","name":"Weight of Love","artist_names":["The Black Keys"],"album_name":"Turn Blue","album_cover_url":"https://i.scdn.co/image/ab67616d00001e021af8fb0d8859055d35d2290f","position":0,"duration":410186,"release_date":"year:2014 month:5 day:9","track_number":1,"disc_number":1}} Jul 17 11:45:39 volumio go-librespot[3036]: time="2025-07-17T11:45:39+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 17 11:45:39 volumio go-librespot[3036]: time="2025-07-17T11:45:39+02:00" level=trace msg="emitting websocket event: playing" Jul 17 11:45:39 volumio volumio[849]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3xMQOd1C3TXsjQ3pmzOmkC","play_origin":"go-librespot"}} Jul 17 11:45:39 volumio volumio[849]: SPOTIFY: PUSH STATE SPOTIFY Jul 17 11:45:39 volumio volumio[849]: SPOTIFY: {"status":"play","service":"spop","title":"Weight of Love","artist":"The Black Keys","album":"Turn Blue","albumart":"https://i.scdn.co/image/ab67616d00001e021af8fb0d8859055d35d2290f","uri":"spotify:track:3xMQOd1C3TXsjQ3pmzOmkC","trackType":"spotify","seek":0,"duration":410,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 17 11:45:39 volumio volumio[849]: info: CoreCommandRouter::servicePushState Jul 17 11:45:39 volumio volumio[849]: info: CorePlayQueue::getTrack 3 Jul 17 11:45:39 volumio volumio[849]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Weight of Love","artist":"The Black Keys","album":"Turn Blue","albumart":"https://i.scdn.co/image/ab67616d00001e021af8fb0d8859055d35d2290f","uri":"spotify:track:3xMQOd1C3TXsjQ3pmzOmkC","trackType":"spotify","seek":0,"duration":410,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 17 11:45:39 volumio volumio[849]: verbose: CURRENT POSITION 3 Jul 17 11:45:39 volumio volumio[849]: info: CoreStateMachine::syncState stateService play Jul 17 11:45:39 volumio volumio[849]: info: CoreStateMachine::syncState currentStatus play Jul 17 11:45:39 volumio volumio[849]: info: Received an update from plugin. extracting info from payload Jul 17 11:45:39 volumio volumio[849]: info: CoreStateMachine::pushState Jul 17 11:45:39 volumio volumio[849]: info: CorePlayQueue::getTrack 3 Jul 17 11:45:39 volumio volumio[849]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 17 11:45:39 volumio volumio[849]: info: CoreCommandRouter::volumioPushState Jul 17 11:45:39 volumio volumio[849]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 17 11:45:39 volumio volumio[849]: Error: channel closed Jul 17 11:45:39 volumio volumio[849]: at FerrumStreamingControlTechnology.updateStateOnPlayer (/data/plugins/user_interface/ferrum_streaming_control_technology/index.js:71:12) Jul 17 11:45:39 volumio volumio[849]: at FerrumStreamingControlTechnology.pushState (/data/plugins/user_interface/ferrum_streaming_control_technology/index.js:183:10) Jul 17 11:45:39 volumio volumio[849]: at /volumio/app/index.js:326:81 Jul 17 11:45:39 volumio volumio[849]: at fastMap (/volumio/node_modules/fast.js/array/map.js:21:17) Jul 17 11:45:39 volumio volumio[849]: at Function.fastMap [as map] (/volumio/node_modules/fast.js/map.js:18:12) Jul 17 11:45:39 volumio volumio[849]: at CoreCommandRouter.volumioPushState (/volumio/app/index.js:324:13) Jul 17 11:45:39 volumio volumio[849]: at CoreStateMachine.pushState (/volumio/app/statemachine.js:532:22) Jul 17 11:45:39 volumio volumio[849]: at CoreStateMachine.syncState (/volumio/app/statemachine.js:762:12) Jul 17 11:45:39 volumio volumio[849]: at CoreCommandRouter.servicePushState (/volumio/app/index.js:414:28) Jul 17 11:45:39 volumio volumio[849]: at ControllerSpotify.pushState (/data/plugins/music_service/spop/index.js:433:31) Jul 17 11:45:39 volumio volumio[849]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:323:14) Jul 17 11:45:39 volumio volumio[849]: at WebSocket.message (/data/plugins/music_service/spop/index.js:193:14) Jul 17 11:45:39 volumio volumio[849]: at WebSocket.emit (events.js:315:20) Jul 17 11:45:39 volumio volumio[849]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Jul 17 11:45:39 volumio volumio[849]: at Receiver.emit (events.js:315:20) Jul 17 11:45:39 volumio volumio[849]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) { Jul 17 11:45:39 volumio volumio[849]: code: 'GenericFailure' Jul 17 11:45:39 volumio volumio[849]: } Jul 17 11:45:39 volumio volumio[849]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 17 11:45:40 volumio sudo[3735]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-07-17 11:44 Jul 17 11:45:40 volumio sudo[3735]: 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="a142ed2648fb91920de0dde3a60cd39b5d0ba4f6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="c82d2341a3a7e284141656a9703a39c694911dfd" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 11 Jul 2025 11:25:34 AM CEST" VOLUMIO_VERSION="3.822" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5fcae8f7c19f114c6b101d5df848236a"