Apr 03 22:46:09 volumiojackusic go-librespot[1886]: time="2026-04-03T22:46:09+13:00" level=trace msg="sent dealer ping" Apr 03 22:46:09 volumiojackusic go-librespot[1886]: time="2026-04-03T22:46:09+13:00" level=trace msg="received dealer pong" Apr 03 22:46:11 volumiojackusic go-librespot[1886]: time="2026-04-03T22:46:11+13:00" level=debug msg="fetched chunk 17/21, size: 524288" uri="spotify:track:3oHvAoxw2xr0Jp7Q94stg8" Apr 03 22:46:18 volumiojackusic volumio[1153]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/ferrum_streaming_control_technology/volumio/bookworm/amd64 Apr 03 22:46:18 volumiojackusic volumio5-onboarding[1845]: time=2026-04-03T22:46:18.483+13:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 03 22:46:21 volumiojackusic volumio[1153]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/ferrum_streaming_control_technology/volumio/bookworm/amd64 Apr 03 22:46:21 volumiojackusic volumio[1153]: info: Folder /tmp/plugins removed Apr 03 22:46:21 volumiojackusic volumio5-onboarding[1845]: time=2026-04-03T22:46:21.650+13:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 03 22:46:21 volumiojackusic volumio5-onboarding[1845]: time=2026-04-03T22:46:21.694+13:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 03 22:46:21 volumiojackusic volumio[1153]: info: Check plugin dependencies Apr 03 22:46:21 volumiojackusic volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 03 22:46:21 volumiojackusic volumio[1153]: info: Checking if plugin already exists Apr 03 22:46:21 volumiojackusic volumio5-onboarding[1845]: time=2026-04-03T22:46:21.708+13:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 03 22:46:21 volumiojackusic volumio5-onboarding[1845]: time=2026-04-03T22:46:21.709+13:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 03 22:46:21 volumiojackusic volumio[1153]: info: Rename folder Apr 03 22:46:21 volumiojackusic volumio[1153]: info: Folder /tmp/downloaded_plugin.zip removed Apr 03 22:46:21 volumiojackusic volumio5-onboarding[1845]: time=2026-04-03T22:46:21.718+13:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 03 22:46:21 volumiojackusic volumio[1153]: info: Move to category Apr 03 22:46:21 volumiojackusic volumio5-onboarding[1845]: time=2026-04-03T22:46:21.951+13:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 03 22:46:21 volumiojackusic volumio[1153]: info: Checking if install.sh is present Apr 03 22:46:21 volumiojackusic volumio[1153]: info: Executing install.sh Apr 03 22:46:21 volumiojackusic sudo[41360]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/user_interface/ferrum_streaming_control_technology/install.sh Apr 03 22:46:21 volumiojackusic sudo[41360]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 03 22:46:21 volumiojackusic sudo[41360]: pam_unix(sudo:session): session closed for user root Apr 03 22:46:21 volumiojackusic volumio[1153]: info: Installing ferrum streaming control technology Dependencies Apr 03 22:46:21 volumiojackusic volumio5-onboarding[1845]: time=2026-04-03T22:46:21.973+13:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 03 22:46:21 volumiojackusic volumio[1153]: Plugin install end detected on script Apr 03 22:46:21 volumiojackusic volumio[1153]: info: Install script completed Apr 03 22:46:21 volumiojackusic volumio5-onboarding[1845]: time=2026-04-03T22:46:21.975+13:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 03 22:46:21 volumiojackusic volumio[1153]: info: Adding reference to registry Apr 03 22:46:21 volumiojackusic volumio5-onboarding[1845]: time=2026-04-03T22:46:21.976+13:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 03 22:46:21 volumiojackusic volumio[1153]: info: Done installing plugin. Apr 03 22:46:21 volumiojackusic volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 03 22:46:21 volumiojackusic volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Apr 03 22:46:21 volumiojackusic volumio[1153]: info: Folder /tmp/plugins removed Apr 03 22:46:21 volumiojackusic volumio[1153]: info: Folder /tmp/downloaded_plugin.zip removed Apr 03 22:46:21 volumiojackusic volumio[1153]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 03 22:46:21 volumiojackusic volumio[1153]: info: Folder /data/temp removed Apr 03 22:46:21 volumiojackusic volumio[1153]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 03 22:46:23 volumiojackusic go-librespot[1886]: time="2026-04-03T22:46:23+13:00" level=debug msg="fetched chunk 18/21, size: 524288" uri="spotify:track:3oHvAoxw2xr0Jp7Q94stg8" Apr 03 22:46:25 volumiojackusic volumio[1153]: info: Enabling plugin ferrum_streaming_control_technology Apr 03 22:46:25 volumiojackusic volumio[1153]: info: Loading plugin "ferrum_streaming_control_technology"... Apr 03 22:46:25 volumiojackusic volumio[1153]: error: !!!! WARNING !!!! Apr 03 22:46:25 volumiojackusic volumio[1153]: 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' Apr 03 22:46:25 volumiojackusic volumio[1153]: Require stack: Apr 03 22:46:25 volumiojackusic volumio[1153]: - /data/plugins/user_interface/ferrum_streaming_control_technology/node_modules/@hemspzoo/fsct-lib/index.js Apr 03 22:46:25 volumiojackusic volumio[1153]: - /data/plugins/user_interface/ferrum_streaming_control_technology/index.js Apr 03 22:46:25 volumiojackusic volumio[1153]: - /volumio/app/pluginmanager.js Apr 03 22:46:25 volumiojackusic volumio[1153]: - /volumio/app/index.js Apr 03 22:46:25 volumiojackusic volumio[1153]: - /volumio/index.js Apr 03 22:46:25 volumiojackusic volumio[1153]: error: Stack trace: Error: Cannot find module '@hemspzoo/fsct-lib-linux-x64-gnu' Apr 03 22:46:25 volumiojackusic volumio[1153]: Require stack: Apr 03 22:46:25 volumiojackusic volumio[1153]: - /data/plugins/user_interface/ferrum_streaming_control_technology/node_modules/@hemspzoo/fsct-lib/index.js Apr 03 22:46:25 volumiojackusic volumio[1153]: - /data/plugins/user_interface/ferrum_streaming_control_technology/index.js Apr 03 22:46:25 volumiojackusic volumio[1153]: - /volumio/app/pluginmanager.js Apr 03 22:46:25 volumiojackusic volumio[1153]: - /volumio/app/index.js Apr 03 22:46:25 volumiojackusic volumio[1153]: - /volumio/index.js Apr 03 22:46:25 volumiojackusic volumio[1153]: at Module._resolveFilename (node:internal/modules/cjs/loader:1048:15) Apr 03 22:46:25 volumiojackusic volumio[1153]: at Module._load (node:internal/modules/cjs/loader:901:27) Apr 03 22:46:25 volumiojackusic volumio[1153]: at Module.require (node:internal/modules/cjs/loader:1115:19) Apr 03 22:46:25 volumiojackusic volumio[1153]: at require (node:internal/modules/helpers:130:18) Apr 03 22:46:25 volumiojackusic volumio[1153]: at Object. (/data/plugins/user_interface/ferrum_streaming_control_technology/node_modules/@hemspzoo/fsct-lib/index.js:190:31) Apr 03 22:46:25 volumiojackusic volumio[1153]: at Module._compile (node:internal/modules/cjs/loader:1233:14) Apr 03 22:46:25 volumiojackusic volumio[1153]: at Module._extensions..js (node:internal/modules/cjs/loader:1287:10) Apr 03 22:46:25 volumiojackusic volumio[1153]: at Module.load (node:internal/modules/cjs/loader:1091:32) Apr 03 22:46:25 volumiojackusic volumio[1153]: at Module._load (node:internal/modules/cjs/loader:938:12) Apr 03 22:46:25 volumiojackusic volumio[1153]: at Module.require (node:internal/modules/cjs/loader:1115:19) Apr 03 22:46:25 volumiojackusic volumio[1153]: at require (node:internal/modules/helpers:130:18) Apr 03 22:46:25 volumiojackusic volumio[1153]: at Object. (/data/plugins/user_interface/ferrum_streaming_control_technology/index.js:25:118) Apr 03 22:46:25 volumiojackusic volumio[1153]: at Module._compile (node:internal/modules/cjs/loader:1233:14) Apr 03 22:46:25 volumiojackusic volumio[1153]: at Module._extensions..js (node:internal/modules/cjs/loader:1287:10) Apr 03 22:46:25 volumiojackusic volumio[1153]: at Module.load (node:internal/modules/cjs/loader:1091:32) Apr 03 22:46:25 volumiojackusic volumio[1153]: at Module._load (node:internal/modules/cjs/loader:938:12) Apr 03 22:46:25 volumiojackusic volumio[1153]: error: !!!! WARNING !!!! Apr 03 22:46:25 volumiojackusic volumio[1153]: info: Done. Apr 03 22:46:25 volumiojackusic volumio[1153]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 03 22:46:36 volumiojackusic go-librespot[1886]: time="2026-04-03T22:46:36+13:00" level=debug msg="fetched chunk 19/21, size: 524288" uri="spotify:track:3oHvAoxw2xr0Jp7Q94stg8" Apr 03 22:46:39 volumiojackusic go-librespot[1886]: time="2026-04-03T22:46:39+13:00" level=trace msg="sent dealer ping" Apr 03 22:46:39 volumiojackusic go-librespot[1886]: time="2026-04-03T22:46:39+13:00" level=trace msg="received dealer pong" Apr 03 22:46:49 volumiojackusic go-librespot[1886]: time="2026-04-03T22:46:49+13:00" level=debug msg="fetched chunk 20/21, size: 524288" uri="spotify:track:3oHvAoxw2xr0Jp7Q94stg8" Apr 03 22:46:52 volumiojackusic volumio[1153]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 03 22:47:02 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:02+13:00" level=debug msg="fetched chunk 21/21, size: 137531" uri="spotify:track:3oHvAoxw2xr0Jp7Q94stg8" Apr 03 22:47:09 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:09+13:00" level=trace msg="sent dealer ping" Apr 03 22:47:09 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:09+13:00" level=trace msg="received dealer pong" Apr 03 22:47:19 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:19+13:00" level=debug msg="prefetching next track" uri="spotify:track:4ghdayYBWL6BZ4If1hVPi5" Apr 03 22:47:20 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:20+13:00" level=debug msg="selected format OGG_VORBIS_320 (999afc8bffb61ed37ff5ae639fb2e422998143e2)" uri="spotify:track:4ghdayYBWL6BZ4If1hVPi5" Apr 03 22:47:20 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:20+13:00" level=debug msg="requested aes key for file 999afc8bffb61ed37ff5ae639fb2e422998143e2, gid: 4ghdayYBWL6BZ4If1hVPi5" Apr 03 22:47:20 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:20+13:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4ghdayYBWL6BZ4If1hVPi5" Apr 03 22:47:20 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:20+13:00" level=debug msg="fetched first chunk of 24, total size is 12361724 bytes" uri="spotify:track:4ghdayYBWL6BZ4If1hVPi5" Apr 03 22:47:20 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:20+13:00" level=info msg="prefetched track \"คลื่น\" (duration: 299000ms)" uri="spotify:track:4ghdayYBWL6BZ4If1hVPi5" Apr 03 22:47:20 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:20+13:00" level=debug msg="fetched chunk 1/23, size: 524288" uri="spotify:track:4ghdayYBWL6BZ4If1hVPi5" Apr 03 22:47:20 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:20+13:00" level=debug msg="fetched chunk 3/23, size: 524288" uri="spotify:track:4ghdayYBWL6BZ4If1hVPi5" Apr 03 22:47:20 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:20+13:00" level=debug msg="fetched chunk 2/23, size: 524288" uri="spotify:track:4ghdayYBWL6BZ4If1hVPi5" Apr 03 22:47:32 volumiojackusic volumio[1153]: info: CoreCommandRouter::volumioGetState Apr 03 22:47:39 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:39+13:00" level=trace msg="sent dealer ping" Apr 03 22:47:39 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:39+13:00" level=trace msg="received dealer pong" Apr 03 22:47:40 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:40+13:00" level=trace msg="received accesspoint ping" Apr 03 22:47:41 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:41+13:00" level=trace msg="received accesspoint pong ack" Apr 03 22:47:45 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:45+13:00" level=trace msg="emitting websocket event: not_playing" Apr 03 22:47:45 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:45+13:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4ghdayYBWL6BZ4If1hVPi5" Apr 03 22:47:45 volumiojackusic volumio[1153]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:playlist:37i9dQZF1E4jWKsYDcOcu0","uri":"spotify:track:3oHvAoxw2xr0Jp7Q94stg8","play_origin":"playlist"}} Apr 03 22:47:45 volumiojackusic volumio[1153]: error: Failed to decode event: not_playing Apr 03 22:47:45 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:45+13:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 03 22:47:45 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:45+13:00" level=trace msg="emitting websocket event: will_play" Apr 03 22:47:45 volumiojackusic volumio[1153]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1E4jWKsYDcOcu0","uri":"spotify:track:4ghdayYBWL6BZ4If1hVPi5","play_origin":"playlist"}} Apr 03 22:47:45 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:45+13:00" level=info msg="loaded track \"คลื่น\" (paused: false, position: 0ms, duration: 299000ms, prefetched: true)" uri="spotify:track:4ghdayYBWL6BZ4If1hVPi5" Apr 03 22:47:45 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:45+13:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 03 22:47:45 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:45+13:00" level=trace msg="scheduling prefetch in 269s" Apr 03 22:47:45 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:45+13:00" level=trace msg="emitting websocket event: metadata" Apr 03 22:47:45 volumiojackusic volumio[1153]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4ghdayYBWL6BZ4If1hVPi5","name":"คลื่น","artist_names":["PRAE CHANAA"],"album_name":"คลื่น","album_cover_url":"https://i.scdn.co/image/ab67616d00001e024aa9f5a7e9baf3ec1cfe866b","position":0,"duration":299000,"release_date":"year:2024 month:11 day:20","track_number":1,"disc_number":1}} Apr 03 22:47:46 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:46+13:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 03 22:47:46 volumiojackusic go-librespot[1886]: time="2026-04-03T22:47:46+13:00" level=trace msg="emitting websocket event: playing" Apr 03 22:47:46 volumiojackusic volumio[1153]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:37i9dQZF1E4jWKsYDcOcu0","uri":"spotify:track:4ghdayYBWL6BZ4If1hVPi5","resume":false,"play_origin":"playlist"}} Apr 03 22:47:46 volumiojackusic volumio[1153]: SPOTIFY: PUSH STATE SPOTIFY Apr 03 22:47:46 volumiojackusic volumio[1153]: SPOTIFY: {"status":"play","service":"spop","title":"คลื่น","artist":"PRAE CHANAA","album":"คลื่น","albumart":"https://i.scdn.co/image/ab67616d00001e024aa9f5a7e9baf3ec1cfe866b","uri":"spotify:track:4ghdayYBWL6BZ4If1hVPi5","trackType":"spotify","seek":0,"duration":299,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 03 22:47:46 volumiojackusic volumio[1153]: info: CoreCommandRouter::servicePushState Apr 03 22:47:46 volumiojackusic volumio[1153]: info: CoreStateMachine::pushState Apr 03 22:47:46 volumiojackusic volumio[1153]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 03 22:47:46 volumiojackusic volumio[1153]: info: CoreCommandRouter::volumioPushState Apr 03 22:47:46 volumiojackusic volumio[1153]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 03 22:47:46 volumiojackusic volumio[1153]: TypeError: Cannot read properties of null (reading 'pushState') Apr 03 22:47:46 volumiojackusic volumio[1153]: at /volumio/app/index.js:326:32 Apr 03 22:47:46 volumiojackusic volumio[1153]: at fastMap (/volumio/node_modules/fast.js/array/map.js:21:17) Apr 03 22:47:46 volumiojackusic volumio[1153]: at Function.fastMap [as map] (/volumio/node_modules/fast.js/map.js:18:12) Apr 03 22:47:46 volumiojackusic volumio[1153]: at CoreCommandRouter.volumioPushState (/volumio/app/index.js:324:13) Apr 03 22:47:46 volumiojackusic volumio[1153]: at CoreStateMachine.pushState (/volumio/app/statemachine.js:534:22) Apr 03 22:47:46 volumiojackusic volumio[1153]: at CoreStateMachine.syncState (/volumio/app/statemachine.js:595:10) Apr 03 22:47:46 volumiojackusic volumio[1153]: at CoreCommandRouter.servicePushState (/volumio/app/index.js:414:28) Apr 03 22:47:46 volumiojackusic volumio[1153]: at ControllerSpotify.pushState (/data/plugins/music_service/spop/index.js:439:31) Apr 03 22:47:46 volumiojackusic volumio[1153]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:329:14) Apr 03 22:47:46 volumiojackusic volumio[1153]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Apr 03 22:47:46 volumiojackusic volumio[1153]: at WebSocket.emit (node:events:514:28) Apr 03 22:47:46 volumiojackusic volumio[1153]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Apr 03 22:47:46 volumiojackusic volumio[1153]: at Receiver.emit (node:events:514:28) Apr 03 22:47:46 volumiojackusic volumio[1153]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Apr 03 22:47:46 volumiojackusic volumio[1153]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Apr 03 22:47:46 volumiojackusic volumio[1153]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Apr 03 22:47:46 volumiojackusic volumio[1153]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 03 22:47:46 volumiojackusic sudo[41590]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-04-03 22:46' Apr 03 22:47:46 volumiojackusic sudo[41590]: 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"