Mar 28 17:56:18 volumio rfkill[20236]: unblock set for type bluetooth Mar 28 17:56:21 volumio bluealsa[1045]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_A4_F8_41_C6_83_A3, ...) Mar 28 17:56:23 volumio bluetoothd[920]: Authentication attempt without agent Mar 28 17:56:23 volumio bluetoothd[920]: profiles/audio/a2dp.c:auth_cb() Access denied: org.bluez.Error.Rejected Mar 28 17:56:23 volumio bluetoothd[920]: Authentication attempt without agent Mar 28 17:56:23 volumio bluetoothd[920]: profiles/audio/avctp.c:auth_cb() Access denied: org.bluez.Error.Rejected Mar 28 17:56:23 volumio bluealsa[1045]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_A4_F8_41_C6_83_A3, ...) Mar 28 17:57:03 volumio volumio[1416]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/ferrum_streaming_control_technology/volumio/bookworm/amd64 Mar 28 17:57:03 volumio volumio5-onboarding[1968]: time=2026-03-28T17:57:03.460+08:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 17:57:05 volumio volumio[1416]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/ferrum_streaming_control_technology/volumio/bookworm/amd64 Mar 28 17:57:05 volumio volumio[1416]: info: Folder /tmp/plugins removed Mar 28 17:57:05 volumio volumio5-onboarding[1968]: time=2026-03-28T17:57:05.298+08:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 17:57:05 volumio volumio5-onboarding[1968]: time=2026-03-28T17:57:05.341+08:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 17:57:05 volumio volumio[1416]: info: Check plugin dependencies Mar 28 17:57:05 volumio volumio[1416]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 17:57:05 volumio volumio5-onboarding[1968]: time=2026-03-28T17:57:05.350+08:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 17:57:05 volumio volumio[1416]: info: Checking if plugin already exists Mar 28 17:57:05 volumio volumio5-onboarding[1968]: time=2026-03-28T17:57:05.351+08:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 17:57:05 volumio volumio[1416]: info: Rename folder Mar 28 17:57:05 volumio volumio[1416]: info: Folder /tmp/downloaded_plugin.zip removed Mar 28 17:57:05 volumio volumio5-onboarding[1968]: time=2026-03-28T17:57:05.359+08:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 17:57:05 volumio volumio[1416]: info: Move to category Mar 28 17:57:05 volumio volumio5-onboarding[1968]: time=2026-03-28T17:57:05.633+08:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 17:57:05 volumio volumio[1416]: info: Checking if install.sh is present Mar 28 17:57:05 volumio volumio[1416]: info: Executing install.sh Mar 28 17:57:05 volumio sudo[20380]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/user_interface/ferrum_streaming_control_technology/install.sh Mar 28 17:57:05 volumio sudo[20380]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 17:57:05 volumio sudo[20380]: pam_unix(sudo:session): session closed for user root Mar 28 17:57:05 volumio volumio[1416]: info: Installing ferrum streaming control technology Dependencies Mar 28 17:57:05 volumio volumio5-onboarding[1968]: time=2026-03-28T17:57:05.656+08:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 17:57:05 volumio volumio[1416]: Plugin install end detected on script Mar 28 17:57:05 volumio volumio[1416]: info: Install script completed Mar 28 17:57:05 volumio volumio5-onboarding[1968]: time=2026-03-28T17:57:05.659+08:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 17:57:05 volumio volumio[1416]: info: Adding reference to registry Mar 28 17:57:05 volumio volumio5-onboarding[1968]: time=2026-03-28T17:57:05.660+08:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 28 17:57:05 volumio volumio[1416]: info: Done installing plugin. Mar 28 17:57:05 volumio volumio[1416]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 17:57:05 volumio volumio[1416]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 28 17:57:05 volumio volumio[1416]: info: Folder /tmp/plugins removed Mar 28 17:57:05 volumio volumio[1416]: info: Folder /tmp/downloaded_plugin.zip removed Mar 28 17:57:05 volumio volumio[1416]: info: Folder /data/temp removed Mar 28 17:57:05 volumio volumio[1416]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 17:57:05 volumio volumio[1416]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 17:57:05 volumio volumio[1416]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 17:57:05 volumio volumio[1416]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 17:57:08 volumio volumio[1416]: info: Enabling plugin ferrum_streaming_control_technology Mar 28 17:57:08 volumio volumio[1416]: info: Loading plugin "ferrum_streaming_control_technology"... Mar 28 17:57:09 volumio volumio[1416]: error: !!!! WARNING !!!! Mar 28 17:57:09 volumio volumio[1416]: error: The plugin user_interface/ferrum_streaming_control_technology failed to load, setting it to stopped. Error: Error: Cannot find module '@hemspzoo/fsct-lib-linux-x64-gnu' Mar 28 17:57:09 volumio volumio[1416]: Require stack: Mar 28 17:57:09 volumio volumio[1416]: - /data/plugins/user_interface/ferrum_streaming_control_technology/node_modules/@hemspzoo/fsct-lib/index.js Mar 28 17:57:09 volumio volumio[1416]: - /data/plugins/user_interface/ferrum_streaming_control_technology/index.js Mar 28 17:57:09 volumio volumio[1416]: - /volumio/app/pluginmanager.js Mar 28 17:57:09 volumio volumio[1416]: - /volumio/app/index.js Mar 28 17:57:09 volumio volumio[1416]: - /volumio/index.js Mar 28 17:57:09 volumio volumio[1416]: error: Stack trace: Error: Cannot find module '@hemspzoo/fsct-lib-linux-x64-gnu' Mar 28 17:57:09 volumio volumio[1416]: Require stack: Mar 28 17:57:09 volumio volumio[1416]: - /data/plugins/user_interface/ferrum_streaming_control_technology/node_modules/@hemspzoo/fsct-lib/index.js Mar 28 17:57:09 volumio volumio[1416]: - /data/plugins/user_interface/ferrum_streaming_control_technology/index.js Mar 28 17:57:09 volumio volumio[1416]: - /volumio/app/pluginmanager.js Mar 28 17:57:09 volumio volumio[1416]: - /volumio/app/index.js Mar 28 17:57:09 volumio volumio[1416]: - /volumio/index.js Mar 28 17:57:09 volumio volumio[1416]: at Module._resolveFilename (node:internal/modules/cjs/loader:1048:15) Mar 28 17:57:09 volumio volumio[1416]: at Module._load (node:internal/modules/cjs/loader:901:27) Mar 28 17:57:09 volumio volumio[1416]: at Module.require (node:internal/modules/cjs/loader:1115:19) Mar 28 17:57:09 volumio volumio[1416]: at require (node:internal/modules/helpers:130:18) Mar 28 17:57:09 volumio volumio[1416]: at Object. (/data/plugins/user_interface/ferrum_streaming_control_technology/node_modules/@hemspzoo/fsct-lib/index.js:190:31) Mar 28 17:57:09 volumio volumio[1416]: at Module._compile (node:internal/modules/cjs/loader:1233:14) Mar 28 17:57:09 volumio volumio[1416]: at Module._extensions..js (node:internal/modules/cjs/loader:1287:10) Mar 28 17:57:09 volumio volumio[1416]: at Module.load (node:internal/modules/cjs/loader:1091:32) Mar 28 17:57:09 volumio volumio[1416]: at Module._load (node:internal/modules/cjs/loader:938:12) Mar 28 17:57:09 volumio volumio[1416]: at Module.require (node:internal/modules/cjs/loader:1115:19) Mar 28 17:57:09 volumio volumio[1416]: at require (node:internal/modules/helpers:130:18) Mar 28 17:57:09 volumio volumio[1416]: at Object. (/data/plugins/user_interface/ferrum_streaming_control_technology/index.js:25:118) Mar 28 17:57:09 volumio volumio[1416]: at Module._compile (node:internal/modules/cjs/loader:1233:14) Mar 28 17:57:09 volumio volumio[1416]: at Module._extensions..js (node:internal/modules/cjs/loader:1287:10) Mar 28 17:57:09 volumio volumio[1416]: at Module.load (node:internal/modules/cjs/loader:1091:32) Mar 28 17:57:09 volumio volumio[1416]: at Module._load (node:internal/modules/cjs/loader:938:12) Mar 28 17:57:09 volumio volumio[1416]: error: !!!! WARNING !!!! Mar 28 17:57:09 volumio volumio[1416]: info: Done. Mar 28 17:57:09 volumio volumio[1416]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 17:57:09 volumio volumio[1416]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 17:57:32 volumio volumio[1416]: info: CorePlayQueue::getTrack 1 Mar 28 17:57:32 volumio volumio[1416]: info: CorePlayQueue::getTrack 2 Mar 28 17:57:32 volumio volumio[1416]: info: Prefetching next song Mar 28 17:57:32 volumio volumio[1416]: info: DOING PREFETCH IN MPD Mar 28 17:57:32 volumio volumio[1416]: verbose: ControllerMpd::sendMpdCommand add "USB/Musics/用101種方式說我愛你CD1/ÖA - LoŶࡥ)101 101 ၗȠysŠTo Qࡡy I Love You [CD1].cue/track0003" Mar 28 17:57:32 volumio volumio[1416]: info: Mar 28 17:57:32 volumio volumio[1416]: ---------------------------- MPD announces system playlist update Mar 28 17:57:32 volumio volumio[1416]: info: Ignoring MPD Status Update Mar 28 17:57:32 volumio volumio[1416]: info: sendMpdCommand add "USB/Musics/用101種方式說我愛你CD1/ÖA - LoŶࡥ)101 101 ၗȠysŠTo Qࡡy I Love You [CD1].cue/track0003" took 0 milliseconds Mar 28 17:57:32 volumio volumio[1416]: verbose: ControllerMpd::sendMpdCommand consume 1 Mar 28 17:57:32 volumio volumio[1416]: info: Mar 28 17:57:32 volumio volumio[1416]: ---------------------------- MPD announces system playlist update Mar 28 17:57:32 volumio volumio[1416]: info: Ignoring MPD Status Update Mar 28 17:57:32 volumio volumio[1416]: info: ------------------------------ 2ms Mar 28 17:57:32 volumio volumio[1416]: info: sendMpdCommand consume 1 took 1 milliseconds Mar 28 17:57:32 volumio volumio[1416]: info: ------------------------------ 1ms Mar 28 17:57:37 volumio volumio[1416]: info: CoreStateMachine::startPlaybackTimer Mar 28 17:57:37 volumio volumio[1416]: info: CorePlayQueue::getTrack 2 Mar 28 17:57:37 volumio volumio[1416]: info: Mar 28 17:57:37 volumio volumio[1416]: ---------------------------- MPD announces system playlist update Mar 28 17:57:37 volumio volumio[1416]: info: Ignoring MPD Status Update Mar 28 17:57:37 volumio volumio[1416]: info: Mar 28 17:57:37 volumio volumio[1416]: ---------------------------- MPD announces state update: player Mar 28 17:57:37 volumio volumio[1416]: info: ControllerMpd::getState Mar 28 17:57:37 volumio volumio[1416]: verbose: ControllerMpd::sendMpdCommand status Mar 28 17:57:37 volumio volumio[1416]: info: Mar 28 17:57:37 volumio volumio[1416]: ---------------------------- MPD announces system playlist update Mar 28 17:57:37 volumio volumio[1416]: info: Ignoring MPD Status Update Mar 28 17:57:37 volumio volumio[1416]: info: Mar 28 17:57:37 volumio volumio[1416]: ---------------------------- MPD announces state update: player Mar 28 17:57:37 volumio volumio[1416]: info: ControllerMpd::getState Mar 28 17:57:37 volumio volumio[1416]: verbose: ControllerMpd::sendMpdCommand status Mar 28 17:57:37 volumio volumio[1416]: info: ------------------------------ 4ms Mar 28 17:57:37 volumio volumio[1416]: info: sendMpdCommand status took 3 milliseconds Mar 28 17:57:37 volumio volumio[1416]: info: ------------------------------ 2ms Mar 28 17:57:37 volumio volumio[1416]: info: sendMpdCommand status took 1 milliseconds Mar 28 17:57:37 volumio volumio[1416]: verbose: ControllerMpd::parseState Mar 28 17:57:37 volumio volumio[1416]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 17:57:37 volumio volumio[1416]: verbose: ControllerMpd::parseState Mar 28 17:57:37 volumio volumio[1416]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 17:57:37 volumio volumio[1416]: info: sendMpdCommand playlistinfo took 1 milliseconds Mar 28 17:57:37 volumio volumio[1416]: info: sendMpdCommand playlistinfo took 0 milliseconds Mar 28 17:57:37 volumio volumio[1416]: verbose: ControllerMpd::parseTrackInfo Mar 28 17:57:37 volumio volumio[1416]: verbose: ControllerMpd::parseTrackInfo Mar 28 17:57:37 volumio volumio[1416]: info: ControllerMpd::pushState Mar 28 17:57:37 volumio volumio[1416]: info: CoreCommandRouter::servicePushState Mar 28 17:57:37 volumio volumio[1416]: info: CorePlayQueue::getTrack 2 Mar 28 17:57:37 volumio volumio[1416]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":280,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"571 Kbps","isStreaming":false,"title":"Way Back Into Love (?q?v ???N?q?????H???D?D??)","artist":"Hugh Grant & Haley Bennett","album":"Love 101 - Disc 1","uri":"USB/Musics/用101種方式說我愛你CD1/ÖA - LoŶࡥ)101 101 ၗȠysŠTo Qࡡy I Love You [CD1].cue/track0003","trackType":""} Mar 28 17:57:37 volumio volumio[1416]: verbose: CURRENT POSITION 2 Mar 28 17:57:37 volumio volumio[1416]: info: CoreStateMachine::syncState stateService play Mar 28 17:57:37 volumio volumio[1416]: info: CoreStateMachine::syncState currentStatus play Mar 28 17:57:37 volumio volumio[1416]: info: Received an update from plugin. extracting info from payload Mar 28 17:57:37 volumio volumio[1416]: info: CoreStateMachine::pushState Mar 28 17:57:37 volumio volumio[1416]: info: CorePlayQueue::getTrack 2 Mar 28 17:57:37 volumio volumio[1416]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 17:57:37 volumio volumio[1416]: info: CoreCommandRouter::volumioPushState Mar 28 17:57:37 volumio volumio[1416]: info: ControllerMpd::pushState Mar 28 17:57:37 volumio volumio[1416]: info: CoreCommandRouter::servicePushState Mar 28 17:57:37 volumio volumio[1416]: info: CorePlayQueue::getTrack 2 Mar 28 17:57:37 volumio volumio[1416]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":280,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"571 Kbps","isStreaming":false,"title":"Way Back Into Love (?q?v ???N?q?????H???D?D??)","artist":"Hugh Grant & Haley Bennett","album":"Love 101 - Disc 1","uri":"USB/Musics/用101種方式說我愛你CD1/ÖA - LoŶࡥ)101 101 ၗȠysŠTo Qࡡy I Love You [CD1].cue/track0003","trackType":""} Mar 28 17:57:37 volumio volumio[1416]: verbose: CURRENT POSITION 2 Mar 28 17:57:37 volumio volumio[1416]: info: CoreStateMachine::syncState stateService play Mar 28 17:57:37 volumio volumio[1416]: info: CoreStateMachine::syncState currentStatus play Mar 28 17:57:37 volumio volumio[1416]: info: Received an update from plugin. extracting info from payload Mar 28 17:57:37 volumio volumio[1416]: info: CoreStateMachine::pushState Mar 28 17:57:37 volumio volumio[1416]: info: CorePlayQueue::getTrack 2 Mar 28 17:57:37 volumio volumio[1416]: info: CoreCommandRouter::volumioPushState Mar 28 17:57:37 volumio volumio5-onboarding[1968]: time=2026-03-28T17:57:37.493+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.18.12:51855,00:00:00:00:00:00%11 @ 0xc000489da0" state=STATUS_PLAYING positionMs=0 volume=20 Mar 28 17:57:37 volumio volumio5-onboarding[1968]: time=2026-03-28T17:57:37.493+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.18.12:51855,00:00:00:00:00:00%11 @ 0xc000489da0" state=STATUS_PLAYING positionMs=0 volume=20 Mar 28 17:57:37 volumio volumio5-onboarding[1968]: time=2026-03-28T17:57:37.494+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.18.12:51855,00:00:00:00:00:00%11 @ 0xc000489da0" id="music-library/USB/Musics/用101種方式說我愛你CD1/ÖA - LoŶࡥ)101 101 ၗȠysŠTo Qࡡy I Love You [CD1].cue/track0003" title="03 - Way Back Into Love (?q?v ???N?q?????H???D?D??)" Mar 28 17:57:37 volumio volumio5-onboarding[1968]: time=2026-03-28T17:57:37.494+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.18.12:51855,00:00:00:00:00:00%11 @ 0xc000489da0" id="music-library/USB/Musics/用101種方式說我愛你CD1/ÖA - LoŶࡥ)101 101 ၗȠysŠTo Qࡡy I Love You [CD1].cue/track0003" title="03 - Way Back Into Love (?q?v ???N?q?????H???D?D??)" Mar 28 17:57:37 volumio volumio[1416]: error: ControllerMpd::pushError: TypeError: Cannot read properties of null (reading 'pushState') Mar 28 17:57:37 volumio volumio[1416]: error: ControllerMpd::pushError: TypeError: Cannot read properties of null (reading 'pushState') Mar 28 17:57:37 volumio volumio[1416]: info: ------------------------------ 13ms Mar 28 17:57:37 volumio volumio[1416]: info: ------------------------------ 12ms Mar 28 17:57:37 volumio volumio[1416]: info: FusionDsp - Volumio is playing Mar 28 17:57:37 volumio volumio[1416]: info: FusionDsp - Volumio is playing Mar 28 17:57:37 volumio volumio[1416]: info: FusionDsp - Volumio is playing Mar 28 17:57:37 volumio volumio[1416]: info: FusionDsp - Volumio is playing Mar 28 17:57:37 volumio volumio[1416]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Mar 28 17:57:37 volumio volumio[1416]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Mar 28 17:57:37 volumio volumio[1416]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Mar 28 17:57:37 volumio volumio[1416]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Mar 28 17:57:37 volumio volumio[1416]: info: CoreStateMachine::pushState Mar 28 17:57:37 volumio volumio[1416]: info: CorePlayQueue::getTrack 2 Mar 28 17:57:37 volumio volumio[1416]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 17:57:37 volumio volumio[1416]: info: CoreCommandRouter::volumioPushState Mar 28 17:57:37 volumio volumio[1416]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 28 17:57:37 volumio volumio[1416]: TypeError: Cannot read properties of null (reading 'pushState') Mar 28 17:57:37 volumio volumio[1416]: at /volumio/app/index.js:326:32 Mar 28 17:57:37 volumio volumio[1416]: at fastMap (/volumio/node_modules/fast.js/array/map.js:21:17) Mar 28 17:57:37 volumio volumio[1416]: at Function.fastMap [as map] (/volumio/node_modules/fast.js/map.js:18:12) Mar 28 17:57:37 volumio volumio[1416]: at CoreCommandRouter.volumioPushState (/volumio/app/index.js:324:13) Mar 28 17:57:37 volumio volumio[1416]: at CoreStateMachine.pushState (/volumio/app/statemachine.js:534:22) Mar 28 17:57:37 volumio volumio[1416]: at listOnTimeout (node:internal/timers:573:17) Mar 28 17:57:37 volumio volumio[1416]: at process.processTimers (node:internal/timers:514:7) Mar 28 17:57:37 volumio volumio[1416]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 28 17:57:37 volumio sudo[20491]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-28 17:56' Mar 28 17:57:37 volumio sudo[20491]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:45:45 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="6bf7cd61fe53483b72878254df87f1c0"