May 31 13:53:03 volumio volumio[1314]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/ferrum_streaming_control_technology/volumio/bookworm/amd64 May 31 13:53:03 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:03.561Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 31 13:53:05 volumio volumio[1314]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/ferrum_streaming_control_technology/volumio/bookworm/amd64 May 31 13:53:05 volumio volumio[1314]: info: Folder /tmp/plugins removed May 31 13:53:05 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:05.327Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 31 13:53:05 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:05.391Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 31 13:53:05 volumio volumio[1314]: info: Check plugin dependencies May 31 13:53:05 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 31 13:53:05 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:05.405Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 31 13:53:05 volumio volumio[1314]: info: Checking if plugin already exists May 31 13:53:05 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:05.411Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 31 13:53:05 volumio volumio[1314]: info: Rename folder May 31 13:53:05 volumio volumio[1314]: info: Folder /tmp/downloaded_plugin.zip removed May 31 13:53:05 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:05.428Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 31 13:53:05 volumio volumio[1314]: info: Move to category May 31 13:53:05 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:05.485Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 31 13:53:05 volumio volumio[1314]: info: Checking if install.sh is present May 31 13:53:05 volumio volumio[1314]: info: Executing install.sh May 31 13:53:05 volumio sudo[11850]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/user_interface/ferrum_streaming_control_technology/install.sh May 31 13:53:05 volumio sudo[11850]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 13:53:05 volumio sudo[11850]: pam_unix(sudo:session): session closed for user root May 31 13:53:05 volumio volumio[1314]: info: Installing ferrum streaming control technology Dependencies May 31 13:53:05 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:05.517Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 31 13:53:05 volumio volumio[1314]: Plugin install end detected on script May 31 13:53:05 volumio volumio[1314]: info: Install script completed May 31 13:53:05 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:05.519Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 31 13:53:05 volumio volumio[1314]: info: Adding reference to registry May 31 13:53:05 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:05.521Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 31 13:53:05 volumio volumio[1314]: info: Done installing plugin. May 31 13:53:05 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 31 13:53:05 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 31 13:53:05 volumio volumio[1314]: info: Folder /tmp/plugins removed May 31 13:53:05 volumio volumio[1314]: info: Folder /tmp/downloaded_plugin.zip removed May 31 13:53:05 volumio volumio[1314]: info: Folder /data/temp removed May 31 13:53:05 volumio volumio[1314]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 13:53:05 volumio volumio[1314]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 13:53:05 volumio volumio[1314]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 13:53:05 volumio volumio[1314]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 13:53:05 volumio volumio[1314]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 13:53:05 volumio volumio[1314]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 13:53:06 volumio volumio[1314]: info: Enabling plugin ferrum_streaming_control_technology May 31 13:53:06 volumio volumio[1314]: info: Loading plugin "ferrum_streaming_control_technology"... May 31 13:53:08 volumio volumio[1314]: error: !!!! WARNING !!!! May 31 13:53:08 volumio volumio[1314]: 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' May 31 13:53:08 volumio volumio[1314]: Require stack: May 31 13:53:08 volumio volumio[1314]: - /data/plugins/user_interface/ferrum_streaming_control_technology/node_modules/@hemspzoo/fsct-lib/index.js May 31 13:53:08 volumio volumio[1314]: - /data/plugins/user_interface/ferrum_streaming_control_technology/index.js May 31 13:53:08 volumio volumio[1314]: - /volumio/app/pluginmanager.js May 31 13:53:08 volumio volumio[1314]: - /volumio/app/index.js May 31 13:53:08 volumio volumio[1314]: - /volumio/index.js May 31 13:53:08 volumio volumio[1314]: error: Stack trace: Error: Cannot find module '@hemspzoo/fsct-lib-linux-x64-gnu' May 31 13:53:08 volumio volumio[1314]: Require stack: May 31 13:53:08 volumio volumio[1314]: - /data/plugins/user_interface/ferrum_streaming_control_technology/node_modules/@hemspzoo/fsct-lib/index.js May 31 13:53:08 volumio volumio[1314]: - /data/plugins/user_interface/ferrum_streaming_control_technology/index.js May 31 13:53:08 volumio volumio[1314]: - /volumio/app/pluginmanager.js May 31 13:53:08 volumio volumio[1314]: - /volumio/app/index.js May 31 13:53:08 volumio volumio[1314]: - /volumio/index.js May 31 13:53:08 volumio volumio[1314]: at Module._resolveFilename (node:internal/modules/cjs/loader:1048:15) May 31 13:53:08 volumio volumio[1314]: at Module._load (node:internal/modules/cjs/loader:901:27) May 31 13:53:08 volumio volumio[1314]: at Module.require (node:internal/modules/cjs/loader:1115:19) May 31 13:53:08 volumio volumio[1314]: at require (node:internal/modules/helpers:130:18) May 31 13:53:08 volumio volumio[1314]: at Object. (/data/plugins/user_interface/ferrum_streaming_control_technology/node_modules/@hemspzoo/fsct-lib/index.js:190:31) May 31 13:53:08 volumio volumio[1314]: at Module._compile (node:internal/modules/cjs/loader:1233:14) May 31 13:53:08 volumio volumio[1314]: at Module._extensions..js (node:internal/modules/cjs/loader:1287:10) May 31 13:53:08 volumio volumio[1314]: at Module.load (node:internal/modules/cjs/loader:1091:32) May 31 13:53:08 volumio volumio[1314]: at Module._load (node:internal/modules/cjs/loader:938:12) May 31 13:53:08 volumio volumio[1314]: at Module.require (node:internal/modules/cjs/loader:1115:19) May 31 13:53:08 volumio volumio[1314]: at require (node:internal/modules/helpers:130:18) May 31 13:53:08 volumio volumio[1314]: at Object. (/data/plugins/user_interface/ferrum_streaming_control_technology/index.js:25:118) May 31 13:53:08 volumio volumio[1314]: at Module._compile (node:internal/modules/cjs/loader:1233:14) May 31 13:53:08 volumio volumio[1314]: at Module._extensions..js (node:internal/modules/cjs/loader:1287:10) May 31 13:53:08 volumio volumio[1314]: at Module.load (node:internal/modules/cjs/loader:1091:32) May 31 13:53:08 volumio volumio[1314]: at Module._load (node:internal/modules/cjs/loader:938:12) May 31 13:53:08 volumio volumio[1314]: error: !!!! WARNING !!!! May 31 13:53:08 volumio volumio[1314]: info: Done. May 31 13:53:08 volumio volumio[1314]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 13:53:08 volumio volumio[1314]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 13:53:08 volumio volumio[1314]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 13:53:10 volumio volumio[1314]: info: CoreCommandRouter::volumioPlay May 31 13:53:10 volumio volumio[1314]: info: CoreStateMachine::play index undefined May 31 13:53:10 volumio volumio[1314]: info: CoreStateMachine::setConsumeUpdateService undefined May 31 13:53:10 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:53:10 volumio volumio[1314]: info: CoreStateMachine::startPlaybackTimer May 31 13:53:10 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:53:10 volumio volumio[1314]: info: [1780224790768] ControllerUPNPBrowser::clearAddPlayTrack May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand stop May 31 13:53:10 volumio volumio[1314]: info: sendMpdCommand stop took 1 milliseconds May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand clear May 31 13:53:10 volumio volumio[1314]: info: May 31 13:53:10 volumio volumio[1314]: ---------------------------- MPD announces system playlist update May 31 13:53:10 volumio volumio[1314]: info: Ignoring MPD Status Update May 31 13:53:10 volumio volumio[1314]: info: sendMpdCommand clear took 0 milliseconds May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand load "http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false" May 31 13:53:10 volumio volumio[1314]: info: May 31 13:53:10 volumio volumio[1314]: ---------------------------- MPD announces system playlist update May 31 13:53:10 volumio volumio[1314]: info: Ignoring MPD Status Update May 31 13:53:10 volumio volumio[1314]: error: updateQueue error: null May 31 13:53:10 volumio volumio[1314]: info: ------------------------------ 1ms May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand add "http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false" May 31 13:53:10 volumio volumio[1314]: error: updateQueue error: null May 31 13:53:10 volumio volumio[1314]: info: ------------------------------ 54ms May 31 13:53:10 volumio volumio[1314]: info: May 31 13:53:10 volumio volumio[1314]: ---------------------------- MPD announces system playlist update May 31 13:53:10 volumio volumio[1314]: info: Ignoring MPD Status Update May 31 13:53:10 volumio volumio[1314]: info: sendMpdCommand add "http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false" took 1 milliseconds May 31 13:53:10 volumio volumio[1314]: info: CoreStateMachine::setConsumeUpdateService mpd May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand play May 31 13:53:10 volumio volumio[1314]: info: May 31 13:53:10 volumio volumio[1314]: ---------------------------- MPD announces system playlist update May 31 13:53:10 volumio volumio[1314]: info: Ignoring MPD Status Update May 31 13:53:10 volumio volumio[1314]: info: ------------------------------ 1ms May 31 13:53:10 volumio volumio[1314]: info: sendMpdCommand play took 2 milliseconds May 31 13:53:10 volumio volumio[1314]: info: ------------------------------ 1ms May 31 13:53:10 volumio volumio[1314]: info: May 31 13:53:10 volumio volumio[1314]: ---------------------------- MPD announces state update: player May 31 13:53:10 volumio volumio[1314]: info: ControllerMpd::getState May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand status May 31 13:53:10 volumio volumio[1314]: info: May 31 13:53:10 volumio volumio[1314]: ---------------------------- MPD announces state update: player May 31 13:53:10 volumio volumio[1314]: info: ControllerMpd::getState May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand status May 31 13:53:10 volumio volumio[1314]: info: sendMpdCommand status took 27 milliseconds May 31 13:53:10 volumio volumio[1314]: info: sendMpdCommand status took 27 milliseconds May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::parseState May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::parseState May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 31 13:53:10 volumio volumio[1314]: info: May 31 13:53:10 volumio volumio[1314]: ---------------------------- MPD announces state update: player May 31 13:53:10 volumio volumio[1314]: info: ControllerMpd::getState May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand status May 31 13:53:10 volumio volumio[1314]: info: May 31 13:53:10 volumio volumio[1314]: ---------------------------- MPD announces state update: player May 31 13:53:10 volumio volumio[1314]: info: ControllerMpd::getState May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand status May 31 13:53:10 volumio volumio[1314]: info: sendMpdCommand playlistinfo took 5 milliseconds May 31 13:53:10 volumio volumio[1314]: info: sendMpdCommand playlistinfo took 5 milliseconds May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::parseTrackInfo May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::parseTrackInfo May 31 13:53:10 volumio volumio[1314]: info: ControllerMpd::pushState May 31 13:53:10 volumio volumio[1314]: info: CoreCommandRouter::servicePushState May 31 13:53:10 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:53:10 volumio volumio[1314]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":299,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"id=27751.wav?format=WAV&downsample=false","artist":null,"album":null,"uri":"http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false","trackType":""} May 31 13:53:10 volumio volumio[1314]: verbose: CURRENT POSITION 26 May 31 13:53:10 volumio volumio[1314]: info: CoreStateMachine::syncState stateService play May 31 13:53:10 volumio volumio[1314]: info: CoreStateMachine::syncState currentStatus stop May 31 13:53:10 volumio volumio[1314]: info: ControllerMpd::pushState May 31 13:53:10 volumio volumio[1314]: info: CoreCommandRouter::servicePushState May 31 13:53:10 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:53:10 volumio volumio[1314]: verbose: STATE SERVICE {"status":"play","position":0,"seek":160,"duration":299,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"id=27751.wav?format=WAV&downsample=false","artist":null,"album":null,"uri":"http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false","trackType":""} May 31 13:53:10 volumio volumio[1314]: verbose: CURRENT POSITION 26 May 31 13:53:10 volumio volumio[1314]: info: CoreStateMachine::syncState stateService play May 31 13:53:10 volumio volumio[1314]: info: CoreStateMachine::syncState currentStatus play May 31 13:53:10 volumio volumio[1314]: info: Received an update from plugin. extracting info from payload May 31 13:53:10 volumio volumio[1314]: info: CoreStateMachine::pushState May 31 13:53:10 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 13:53:10 volumio volumio[1314]: info: CoreCommandRouter::volumioPushState May 31 13:53:10 volumio volumio[1314]: info: ------------------------------ 46ms May 31 13:53:10 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:10.948Z level=INFO msg="emitting player state changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" state=STATUS_PLAYING positionMs=0 volume=48 May 31 13:53:10 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:10.948Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" id="http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false" title="id=27751.wav?format=WAV&downsample=false" May 31 13:53:10 volumio volumio[1314]: error: ControllerMpd::pushError: TypeError: Cannot read properties of null (reading 'pushState') May 31 13:53:10 volumio volumio[1314]: info: ------------------------------ 49ms May 31 13:53:10 volumio volumio[1314]: info: sendMpdCommand status took 17 milliseconds May 31 13:53:10 volumio volumio[1314]: info: sendMpdCommand status took 17 milliseconds May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::parseState May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::parseState May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 31 13:53:10 volumio volumio[1314]: info: FusionDsp - Volumio is playing May 31 13:53:10 volumio volumio[1314]: warn: FusionDsp - Monitor WebSocket not open, skipping commands May 31 13:53:10 volumio volumio[1314]: info: [LastFM] Current track does not have sufficient metadata: Missing artist. Not a composite title! id=27751.wav?format=WAV&downsample=false May 31 13:53:10 volumio volumio[1314]: info: camilladsp respawn in 1000 ms (attempt 1/10) May 31 13:53:10 volumio volumio[1314]: info: sendMpdCommand playlistinfo took 42 milliseconds May 31 13:53:10 volumio volumio[1314]: info: sendMpdCommand playlistinfo took 42 milliseconds May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::parseTrackInfo May 31 13:53:10 volumio volumio[1314]: verbose: ControllerMpd::parseTrackInfo May 31 13:53:10 volumio volumio[1314]: info: ControllerMpd::pushState May 31 13:53:10 volumio volumio[1314]: info: CoreCommandRouter::servicePushState May 31 13:53:10 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:53:10 volumio volumio[1314]: verbose: STATE SERVICE {"status":"play","position":0,"seek":958,"duration":299,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"id=27751.wav?format=WAV&downsample=false","artist":null,"album":null,"uri":"http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false","trackType":""} May 31 13:53:10 volumio volumio[1314]: verbose: CURRENT POSITION 26 May 31 13:53:10 volumio volumio[1314]: info: CoreStateMachine::syncState stateService play May 31 13:53:10 volumio volumio[1314]: info: CoreStateMachine::syncState currentStatus play May 31 13:53:10 volumio volumio[1314]: info: Received an update from plugin. extracting info from payload May 31 13:53:10 volumio volumio[1314]: info: CoreStateMachine::pushState May 31 13:53:10 volumio volumio[1314]: info: CoreCommandRouter::volumioPushState May 31 13:53:11 volumio volumio[1314]: info: ControllerMpd::pushState May 31 13:53:11 volumio volumio[1314]: info: CoreCommandRouter::servicePushState May 31 13:53:11 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:53:11 volumio volumio[1314]: verbose: STATE SERVICE {"status":"play","position":0,"seek":958,"duration":299,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"id=27751.wav?format=WAV&downsample=false","artist":null,"album":null,"uri":"http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false","trackType":""} May 31 13:53:11 volumio volumio[1314]: verbose: CURRENT POSITION 26 May 31 13:53:11 volumio volumio[1314]: info: CoreStateMachine::syncState stateService play May 31 13:53:11 volumio volumio[1314]: info: CoreStateMachine::syncState currentStatus play May 31 13:53:11 volumio volumio[1314]: info: Received an update from plugin. extracting info from payload May 31 13:53:11 volumio volumio[1314]: info: CoreStateMachine::pushState May 31 13:53:11 volumio volumio[1314]: info: CoreCommandRouter::volumioPushState May 31 13:53:11 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:11.001Z level=INFO msg="emitting player state changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" state=STATUS_PLAYING positionMs=0 volume=48 May 31 13:53:11 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:11.001Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" id="http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false" title="id=27751.wav?format=WAV&downsample=false" May 31 13:53:11 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:11.002Z level=INFO msg="emitting player state changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" state=STATUS_PLAYING positionMs=0 volume=48 May 31 13:53:11 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:11.002Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" id="http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false" title="id=27751.wav?format=WAV&downsample=false" May 31 13:53:11 volumio volumio[1314]: error: ControllerMpd::pushError: TypeError: Cannot read properties of null (reading 'pushState') May 31 13:53:11 volumio volumio[1314]: error: ControllerMpd::pushError: TypeError: Cannot read properties of null (reading 'pushState') May 31 13:53:11 volumio volumio[1314]: info: ------------------------------ 77ms May 31 13:53:11 volumio volumio[1314]: info: ------------------------------ 73ms May 31 13:53:11 volumio volumio[1314]: info: FusionDsp - Volumio is playing May 31 13:53:11 volumio volumio[1314]: info: FusionDsp - Volumio is playing May 31 13:53:11 volumio volumio[1314]: info: [LastFM] Current track does not have sufficient metadata: Missing artist. Not a composite title! id=27751.wav?format=WAV&downsample=false May 31 13:53:11 volumio volumio[1314]: error: FusionDsp - Monitor WebSocket error: [object Object] May 31 13:53:11 volumio volumio[1314]: info: FusionDsp - Clipping Monitor reconnecting in 2000ms May 31 13:53:11 volumio volumio[1314]: error: FusionDsp - Monitor WebSocket error: [object Object] May 31 13:53:11 volumio volumio[1314]: info: FusionDsp - Clipping Monitor reconnecting in 4000ms May 31 13:53:11 volumio volumio[1314]: error: FusionDsp - Monitor WebSocket error: [object Object] May 31 13:53:11 volumio volumio[1314]: info: FusionDsp - Clipping Monitor reconnecting in 8000ms May 31 13:53:11 volumio volumio[1314]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 May 31 13:53:11 volumio volumio[1314]: info: FusionDsp - ---- read samplerate from file: 44100 May 31 13:53:11 volumio volumio[1314]: info: camilladsp service terminated, instance 1 May 31 13:53:11 volumio volumio[1314]: info: FusionDsp - If filter freq >samplerate/2 then disable it May 31 13:53:11 volumio volumio[1314]: info: camilladsp service started and running in background, instance 1 May 31 13:53:11 volumio volumio[1314]: info: camilladsp respawn in 1000 ms (attempt 1/10) May 31 13:53:12 volumio volumio[1314]: info: camilladsp respawn in 2000 ms (attempt 2/10) May 31 13:53:12 volumio volumio[1314]: info: camilladsp respawn in 4000 ms (attempt 3/10) May 31 13:53:13 volumio volumio[1314]: error: FusionDsp - Monitor WebSocket error: [object Object] May 31 13:53:13 volumio volumio[1314]: info: FusionDsp - Clipping Monitor reconnecting in 16000ms May 31 13:53:14 volumio volumio[1314]: info: camilladsp respawn in 8000 ms (attempt 4/10) May 31 13:53:15 volumio volumio[1314]: error: FusionDsp - Monitor WebSocket error: [object Object] May 31 13:53:15 volumio volumio[1314]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms May 31 13:53:16 volumio volumio[1314]: info: camilladsp respawn in 10000 ms (attempt 5/10) May 31 13:53:19 volumio volumio[1314]: error: FusionDsp - Monitor WebSocket error: [object Object] May 31 13:53:19 volumio volumio[1314]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms May 31 13:53:20 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 31 13:53:20 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 31 13:53:20 volumio volumio[1314]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 13:53:20 volumio volumio[1314]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 13:53:22 volumio volumio[1314]: info: camilladsp respawn in 10000 ms (attempt 6/10) May 31 13:53:26 volumio volumio[1314]: info: camilladsp respawn in 10000 ms (attempt 7/10) May 31 13:53:29 volumio volumio[1314]: error: FusionDsp - Monitor WebSocket error: [object Object] May 31 13:53:29 volumio volumio[1314]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms May 31 13:53:30 volumio volumio[1314]: warn: FusionDsp - Monitor WebSocket not open, skipping commands May 31 13:53:32 volumio volumio[1314]: info: camilladsp respawn in 10000 ms (attempt 8/10) May 31 13:53:34 volumio volumio[1314]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 13:53:34 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 31 13:53:34 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 31 13:53:34 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 31 13:53:34 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs May 31 13:53:34 volumio volumio[1314]: info: Received Get System Version May 31 13:53:34 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 31 13:53:36 volumio volumio[1314]: info: camilladsp respawn in 10000 ms (attempt 9/10) May 31 13:53:39 volumio volumio[1314]: info: CoreCommandRouter::volumioPause May 31 13:53:39 volumio volumio[1314]: info: CoreStateMachine::pause May 31 13:53:39 volumio volumio[1314]: info: CoreStateMachine::stPlaybackTimer May 31 13:53:39 volumio volumio[1314]: info: CoreStateMachine::servicePause May 31 13:53:39 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:53:39 volumio volumio[1314]: info: CoreCommandRouter::servicePause May 31 13:53:39 volumio volumio[1314]: info: [1780224819513] ControllerUPNPBrowser::pause May 31 13:53:39 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand pause May 31 13:53:39 volumio volumio[1314]: info: May 31 13:53:39 volumio volumio[1314]: ---------------------------- MPD announces state update: player May 31 13:53:39 volumio volumio[1314]: info: sendMpdCommand pause took 1 milliseconds May 31 13:53:39 volumio volumio[1314]: info: ControllerMpd::getState May 31 13:53:39 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand status May 31 13:53:39 volumio volumio[1314]: info: May 31 13:53:39 volumio volumio[1314]: ---------------------------- MPD announces state update: player May 31 13:53:39 volumio volumio[1314]: info: ControllerMpd::getState May 31 13:53:39 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand status May 31 13:53:39 volumio volumio[1314]: info: sendMpdCommand status took 1 milliseconds May 31 13:53:39 volumio volumio[1314]: verbose: ControllerMpd::parseState May 31 13:53:39 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 31 13:53:39 volumio volumio[1314]: info: sendMpdCommand status took 1 milliseconds May 31 13:53:39 volumio volumio[1314]: info: sendMpdCommand playlistinfo took 0 milliseconds May 31 13:53:39 volumio volumio[1314]: verbose: ControllerMpd::parseState May 31 13:53:39 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 31 13:53:39 volumio volumio[1314]: verbose: ControllerMpd::parseTrackInfo May 31 13:53:39 volumio volumio[1314]: info: ControllerMpd::pushState May 31 13:53:39 volumio volumio[1314]: info: CoreCommandRouter::servicePushState May 31 13:53:39 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:53:39 volumio volumio[1314]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":958,"duration":299,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"id=27751.wav?format=WAV&downsample=false","artist":null,"album":null,"uri":"http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false","trackType":""} May 31 13:53:39 volumio volumio[1314]: verbose: CURRENT POSITION 26 May 31 13:53:39 volumio volumio[1314]: info: CoreStateMachine::syncState stateService pause May 31 13:53:39 volumio volumio[1314]: info: CoreStateMachine::syncState currentStatus pause May 31 13:53:39 volumio volumio[1314]: info: CoreStateMachine::pushState May 31 13:53:39 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 13:53:39 volumio volumio[1314]: info: CoreCommandRouter::volumioPushState May 31 13:53:39 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:39.519Z level=INFO msg="emitting player state changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" state=STATUS_PAUSED positionMs=28527 volume=48 May 31 13:53:39 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:39.520Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" id="http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false" title="id=27751.wav?format=WAV&downsample=false" May 31 13:53:39 volumio volumio[1314]: error: ControllerMpd::pushError: TypeError: Cannot read properties of null (reading 'pushState') May 31 13:53:39 volumio volumio[1314]: info: ------------------------------ 6ms May 31 13:53:39 volumio volumio[1314]: info: sendMpdCommand playlistinfo took 6 milliseconds May 31 13:53:39 volumio volumio[1314]: verbose: ControllerMpd::parseTrackInfo May 31 13:53:39 volumio volumio[1314]: info: ControllerMpd::pushState May 31 13:53:39 volumio volumio[1314]: info: CoreCommandRouter::servicePushState May 31 13:53:39 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:53:39 volumio volumio[1314]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":958,"duration":299,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"id=27751.wav?format=WAV&downsample=false","artist":null,"album":null,"uri":"http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false","trackType":""} May 31 13:53:39 volumio volumio[1314]: verbose: CURRENT POSITION 26 May 31 13:53:39 volumio volumio[1314]: info: CoreStateMachine::syncState stateService pause May 31 13:53:39 volumio volumio[1314]: info: CoreStateMachine::syncState currentStatus pause May 31 13:53:39 volumio volumio[1314]: info: CoreStateMachine::pushState May 31 13:53:39 volumio volumio[1314]: info: CoreCommandRouter::volumioPushState May 31 13:53:39 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:39.528Z level=INFO msg="emitting player state changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" state=STATUS_PAUSED positionMs=28527 volume=48 May 31 13:53:39 volumio volumio[1314]: error: ControllerMpd::pushError: TypeError: Cannot read properties of null (reading 'pushState') May 31 13:53:39 volumio volumio[1314]: info: ------------------------------ 15ms May 31 13:53:39 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:39.529Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" id="http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false" title="id=27751.wav?format=WAV&downsample=false" May 31 13:53:39 volumio volumio[1314]: info: FusionDsp - Volumio is not playing May 31 13:53:39 volumio volumio[1314]: info: FusionDsp - Clipped samples monitor stopped May 31 13:53:39 volumio volumio[1314]: info: FusionDsp - Volumio is not playing May 31 13:53:39 volumio volumio[1314]: info: FusionDsp - Clipped samples monitor stopped May 31 13:53:40 volumio volumio[1314]: info: CoreCommandRouter::volumioPlay May 31 13:53:40 volumio volumio[1314]: info: CoreStateMachine::play index undefined May 31 13:53:40 volumio volumio[1314]: info: CoreStateMachine::setConsumeUpdateService undefined May 31 13:53:40 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:53:40 volumio volumio[1314]: info: CoreStateMachine::startPlaybackTimer May 31 13:53:40 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:53:40 volumio volumio[1314]: info: [1780224820275] ControllerUPNPBrowser::resume May 31 13:53:40 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand play May 31 13:53:40 volumio volumio[1314]: info: sendMpdCommand play took 3 milliseconds May 31 13:53:40 volumio volumio[1314]: info: May 31 13:53:40 volumio volumio[1314]: ---------------------------- MPD announces state update: player May 31 13:53:40 volumio volumio[1314]: info: ControllerMpd::getState May 31 13:53:40 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand status May 31 13:53:40 volumio volumio[1314]: info: May 31 13:53:40 volumio volumio[1314]: ---------------------------- MPD announces state update: player May 31 13:53:40 volumio volumio[1314]: info: ControllerMpd::getState May 31 13:53:40 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand status May 31 13:53:40 volumio volumio[1314]: info: sendMpdCommand status took 1 milliseconds May 31 13:53:40 volumio volumio[1314]: verbose: ControllerMpd::parseState May 31 13:53:40 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 31 13:53:40 volumio volumio[1314]: info: sendMpdCommand status took 0 milliseconds May 31 13:53:40 volumio volumio[1314]: info: sendMpdCommand playlistinfo took 1 milliseconds May 31 13:53:40 volumio volumio[1314]: verbose: ControllerMpd::parseState May 31 13:53:40 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 31 13:53:40 volumio volumio[1314]: verbose: ControllerMpd::parseTrackInfo May 31 13:53:40 volumio volumio[1314]: info: ControllerMpd::pushState May 31 13:53:40 volumio volumio[1314]: info: CoreCommandRouter::servicePushState May 31 13:53:40 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:53:40 volumio volumio[1314]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1939,"duration":299,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"id=27751.wav?format=WAV&downsample=false","artist":null,"album":null,"uri":"http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false","trackType":""} May 31 13:53:40 volumio volumio[1314]: verbose: CURRENT POSITION 26 May 31 13:53:40 volumio volumio[1314]: info: CoreStateMachine::syncState stateService play May 31 13:53:40 volumio volumio[1314]: info: CoreStateMachine::syncState currentStatus pause May 31 13:53:40 volumio volumio[1314]: info: CoreStateMachine::pushState May 31 13:53:40 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:53:40 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 13:53:40 volumio volumio[1314]: info: CoreCommandRouter::volumioPushState May 31 13:53:40 volumio volumio[1314]: error: ControllerMpd::pushError: TypeError: Cannot read properties of null (reading 'pushState') May 31 13:53:40 volumio volumio[1314]: info: ------------------------------ 5ms May 31 13:53:40 volumio volumio[1314]: info: sendMpdCommand playlistinfo took 3 milliseconds May 31 13:53:40 volumio volumio[1314]: verbose: ControllerMpd::parseTrackInfo May 31 13:53:40 volumio volumio[1314]: info: ControllerMpd::pushState May 31 13:53:40 volumio volumio[1314]: info: CoreCommandRouter::servicePushState May 31 13:53:40 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:53:40 volumio volumio[1314]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1939,"duration":299,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"id=27751.wav?format=WAV&downsample=false","artist":null,"album":null,"uri":"http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false","trackType":""} May 31 13:53:40 volumio volumio[1314]: verbose: CURRENT POSITION 26 May 31 13:53:40 volumio volumio[1314]: info: CoreStateMachine::syncState stateService play May 31 13:53:40 volumio volumio[1314]: info: CoreStateMachine::syncState currentStatus play May 31 13:53:40 volumio volumio[1314]: info: Received an update from plugin. extracting info from payload May 31 13:53:40 volumio volumio[1314]: info: CoreStateMachine::pushState May 31 13:53:40 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:53:40 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 13:53:40 volumio volumio[1314]: info: CoreCommandRouter::volumioPushState May 31 13:53:40 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:40.285Z level=INFO msg="emitting player state changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" state=STATUS_PLAYING positionMs=29217 volume=48 May 31 13:53:40 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:40.286Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" id="http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false" title=Sleep.flac May 31 13:53:40 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:40.287Z level=INFO msg="emitting player state changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" state=STATUS_PLAYING positionMs=1939 volume=48 May 31 13:53:40 volumio volumio[1314]: error: ControllerMpd::pushError: TypeError: Cannot read properties of null (reading 'pushState') May 31 13:53:40 volumio volumio5-onboarding[1869]: time=2026-05-31T10:53:40.287Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" id="http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false" title=Sleep.flac May 31 13:53:40 volumio volumio[1314]: info: ------------------------------ 7ms May 31 13:53:40 volumio volumio[1314]: info: CoreCommandRouter::volumioGetQueue May 31 13:53:40 volumio volumio[1314]: info: CoreStateMachine::getQueue May 31 13:53:40 volumio volumio[1314]: info: CorePlayQueue::getQueue May 31 13:53:40 volumio volumio[1314]: info: CoreCommandRouter::volumioGetQueue May 31 13:53:40 volumio volumio[1314]: info: CoreStateMachine::getQueue May 31 13:53:40 volumio volumio[1314]: info: CorePlayQueue::getQueue May 31 13:53:40 volumio volumio[1314]: info: FusionDsp - Volumio is playing May 31 13:53:40 volumio volumio[1314]: warn: FusionDsp - Monitor WebSocket not open, skipping commands May 31 13:53:40 volumio volumio[1314]: info: FusionDsp - Volumio is playing May 31 13:53:40 volumio volumio[1314]: info: [LastFM] Current track has sufficient metadata: title (Sleep.flac) and artist (Poets Of The Fall) passed on explicitly May 31 13:53:40 volumio volumio[1314]: error: [LastFM] plugin is not authenticated, please retry, or track info could not be determined (very rare) May 31 13:53:40 volumio volumio[1314]: info: [LastFM] updating timer, previous duration is obsolete; adding 750 milliseconds. May 31 13:53:40 volumio volumio[1314]: Currently remaining: 223500 May 31 13:53:40 volumio volumio[1314]: -------------------------------------------------// Adding 750 milliseconds to a total of 224250. May 31 13:53:40 volumio volumio[1314]: error: FusionDsp - Monitor WebSocket error: [object Object] May 31 13:53:40 volumio volumio[1314]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms May 31 13:53:40 volumio volumio[1314]: error: FusionDsp - Monitor WebSocket error: [object Object] May 31 13:53:40 volumio volumio[1314]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms May 31 13:53:40 volumio volumio[1314]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 May 31 13:53:40 volumio volumio[1314]: info: FusionDsp - ---- read samplerate from file: 44100 May 31 13:53:40 volumio volumio[1314]: info: FusionDsp - If filter freq >samplerate/2 then disable it May 31 13:53:40 volumio volumio[1314]: error: FusionDsp - Reload WebSocket error: [object Object] May 31 13:53:42 volumio volumio[1314]: info: camilladsp respawn in 10000 ms (attempt 10/10) May 31 13:53:45 volumio volumio[1314]: error: FusionDsp - Monitor WebSocket error: [object Object] May 31 13:53:45 volumio volumio[1314]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms May 31 13:53:46 volumio volumio[1314]: error: camilladsp exceeded max consecutive respawns (10); stopping respawn. Plugin restart required. May 31 13:53:49 volumio volumio[1314]: error: FusionDsp - Monitor WebSocket error: [object Object] May 31 13:53:49 volumio volumio[1314]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms May 31 13:53:52 volumio volumio[1314]: warn: camilladsp respawn stopped due to repeated failures; not respawning May 31 13:53:59 volumio volumio[1314]: error: FusionDsp - Monitor WebSocket error: [object Object] May 31 13:53:59 volumio volumio[1314]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms May 31 13:54:00 volumio volumio[1314]: warn: FusionDsp - Monitor WebSocket not open, skipping commands May 31 13:54:09 volumio volumio[1314]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 13:54:09 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions May 31 13:54:09 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 31 13:54:09 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 31 13:54:09 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 13:54:09 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 13:54:09 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 13:54:09 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 13:54:09 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 13:54:09 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 13:54:09 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 13:54:09 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode May 31 13:54:09 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus May 31 13:54:10 volumio volumio[1314]: error: FusionDsp - Monitor WebSocket error: [object Object] May 31 13:54:10 volumio volumio[1314]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms May 31 13:54:10 volumio volumio[1314]: error: FusionDsp - Monitor WebSocket error: [object Object] May 31 13:54:10 volumio volumio[1314]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms May 31 13:54:12 volumio volumio[1314]: info: CALLMETHOD: audio_interface alsa_controller saveAlsaOptions [object Object] May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveAlsaOptions May 31 13:54:12 volumio volumio[1314]: info: Preparing to save Alsa Options, stopping services first May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::volumioGetState May 31 13:54:12 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::volumioPause May 31 13:54:12 volumio volumio[1314]: info: CoreStateMachine::pause May 31 13:54:12 volumio volumio[1314]: info: CoreStateMachine::stPlaybackTimer May 31 13:54:12 volumio volumio[1314]: info: CoreStateMachine::servicePause May 31 13:54:12 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::servicePause May 31 13:54:12 volumio volumio[1314]: info: [1780224852173] ControllerUPNPBrowser::pause May 31 13:54:12 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand pause May 31 13:54:12 volumio volumio[1314]: info: Saving Audio Output to: {"output_device":{"value":"0,3","label":"HDMI"}} May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 31 13:54:12 volumio volumio[1314]: info: Found match in Cards Database: setting mixer for card HDMI May 31 13:54:12 volumio volumio[1314]: info: Setting default mixerSoftMaster for Softvolume device May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::volumioUpdateVolumeSettings May 31 13:54:12 volumio volumio[1314]: info: Updating Volume Controller Parameters: Device: 0,3 Name: softvolume Mixer: SoftMaster Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume May 31 13:54:12 volumio volumio[1314]: info: Disabling external Volume Control May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 13:54:12 volumio volumio[1314]: info: Enable softmixer device for audio device undefined May 31 13:54:12 volumio volumio[1314]: info: CoreStateMachine::pushState May 31 13:54:12 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::volumioPushState May 31 13:54:12 volumio volumio[1314]: info: May 31 13:54:12 volumio volumio[1314]: ---------------------------- MPD announces state update: player May 31 13:54:12 volumio volumio5-onboarding[1869]: time=2026-05-31T10:54:12.258Z level=INFO msg="emitting player state changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" state=STATUS_PAUSED positionMs=33767 volume=100 May 31 13:54:12 volumio volumio5-onboarding[1869]: time=2026-05-31T10:54:12.258Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" id="http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false" title=Sleep.flac May 31 13:54:12 volumio volumio[1314]: info: sendMpdCommand pause took 86 milliseconds May 31 13:54:12 volumio volumio[1314]: info: ControllerMpd::getState May 31 13:54:12 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand status May 31 13:54:12 volumio volumio[1314]: info: May 31 13:54:12 volumio volumio[1314]: ---------------------------- MPD announces state update: player May 31 13:54:12 volumio volumio[1314]: info: ControllerMpd::getState May 31 13:54:12 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand status May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::volumioGetQueue May 31 13:54:12 volumio volumio[1314]: info: CoreStateMachine::getQueue May 31 13:54:12 volumio volumio[1314]: info: CorePlayQueue::getQueue May 31 13:54:12 volumio volumio[1314]: info: FusionDsp - Volumio is not playing May 31 13:54:12 volumio volumio[1314]: info: FusionDsp - Clipped samples monitor stopped May 31 13:54:12 volumio volumio[1314]: info: Software Volume ALSA configuration written May 31 13:54:12 volumio volumio[1314]: info: Preparing to generate the ALSA configuration file May 31 13:54:12 volumio volumio[1314]: info: sendMpdCommand status took 16 milliseconds May 31 13:54:12 volumio volumio[1314]: info: sendMpdCommand status took 16 milliseconds May 31 13:54:12 volumio volumio[1314]: verbose: ControllerMpd::parseState May 31 13:54:12 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 31 13:54:12 volumio volumio[1314]: verbose: ControllerMpd::parseState May 31 13:54:12 volumio volumio[1314]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus May 31 13:54:12 volumio volumio[1314]: info: sendMpdCommand playlistinfo took 68 milliseconds May 31 13:54:12 volumio volumio[1314]: info: sendMpdCommand playlistinfo took 68 milliseconds May 31 13:54:12 volumio volumio[1314]: verbose: ControllerMpd::parseTrackInfo May 31 13:54:12 volumio volumio[1314]: verbose: ControllerMpd::parseTrackInfo May 31 13:54:12 volumio volumio[1314]: info: ControllerMpd::pushState May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::servicePushState May 31 13:54:12 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:54:12 volumio volumio[1314]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":1939,"duration":299,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"id=27751.wav?format=WAV&downsample=false","artist":null,"album":null,"uri":"http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false","trackType":""} May 31 13:54:12 volumio volumio[1314]: verbose: CURRENT POSITION 26 May 31 13:54:12 volumio volumio[1314]: info: CoreStateMachine::syncState stateService pause May 31 13:54:12 volumio volumio[1314]: info: CoreStateMachine::syncState currentStatus pause May 31 13:54:12 volumio volumio[1314]: info: CoreStateMachine::pushState May 31 13:54:12 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::volumioPushState May 31 13:54:12 volumio volumio[1314]: info: ControllerMpd::pushState May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::servicePushState May 31 13:54:12 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:54:12 volumio volumio[1314]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":1939,"duration":299,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"id=27751.wav?format=WAV&downsample=false","artist":null,"album":null,"uri":"http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false","trackType":""} May 31 13:54:12 volumio volumio[1314]: verbose: CURRENT POSITION 26 May 31 13:54:12 volumio volumio[1314]: info: CoreStateMachine::syncState stateService pause May 31 13:54:12 volumio volumio[1314]: info: CoreStateMachine::syncState currentStatus pause May 31 13:54:12 volumio volumio[1314]: info: CoreStateMachine::pushState May 31 13:54:12 volumio volumio[1314]: info: CorePlayQueue::getTrack 26 May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::volumioPushState May 31 13:54:12 volumio volumio5-onboarding[1869]: time=2026-05-31T10:54:12.357Z level=INFO msg="emitting player state changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" state=STATUS_PAUSED positionMs=33767 volume=100 May 31 13:54:12 volumio volumio5-onboarding[1869]: time=2026-05-31T10:54:12.357Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" id="http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false" title=Sleep.flac May 31 13:54:12 volumio volumio5-onboarding[1869]: time=2026-05-31T10:54:12.362Z level=INFO msg="emitting player state changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" state=STATUS_PAUSED positionMs=33767 volume=100 May 31 13:54:12 volumio volumio5-onboarding[1869]: time=2026-05-31T10:54:12.363Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.59:60186 @ 0xc000260300" id="http://192.168.1.142:50002/transcoder/genericoder.cgi/id=27751.wav?format=WAV&downsample=false" title=Sleep.flac May 31 13:54:12 volumio volumio[1314]: error: ControllerMpd::pushError: TypeError: Cannot read properties of null (reading 'pushState') May 31 13:54:12 volumio volumio[1314]: error: ControllerMpd::pushError: TypeError: Cannot read properties of null (reading 'pushState') May 31 13:54:12 volumio volumio[1314]: info: ------------------------------ 111ms May 31 13:54:12 volumio volumio[1314]: info: ------------------------------ 109ms May 31 13:54:12 volumio volumio[1314]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf May 31 13:54:12 volumio volumio[1314]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf May 31 13:54:12 volumio volumio[1314]: info: The plugin stylish_player has an ALSA contribution file sp_in.sp_out.7.conf May 31 13:54:12 volumio volumio[1314]: info: Reading ALSA contributions from plugins. May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::volumioGetQueue May 31 13:54:12 volumio volumio[1314]: info: CoreStateMachine::getQueue May 31 13:54:12 volumio volumio[1314]: info: CorePlayQueue::getQueue May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::volumioGetQueue May 31 13:54:12 volumio volumio[1314]: info: CoreStateMachine::getQueue May 31 13:54:12 volumio volumio[1314]: info: CorePlayQueue::getQueue May 31 13:54:12 volumio volumio[1314]: info: FusionDsp - Volumio is not playing May 31 13:54:12 volumio volumio[1314]: info: FusionDsp - Clipped samples monitor stopped May 31 13:54:12 volumio volumio[1314]: info: FusionDsp - Volumio is not playing May 31 13:54:12 volumio volumio[1314]: info: FusionDsp - Clipped samples monitor stopped May 31 13:54:12 volumio volumio[1314]: info: Asound.conf file unchanged, so no further update is needed May 31 13:54:12 volumio volumio[1314]: info: Output device has changed, restarting MPD May 31 13:54:12 volumio volumio[1314]: info: Output device has changed, restarting Shairport Sync May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 31 13:54:12 volumio sudo[12196]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 31 13:54:12 volumio sudo[12196]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 13:54:12 volumio sudo[12196]: pam_unix(sudo:session): session closed for user root May 31 13:54:12 volumio sudo[12198]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 31 13:54:12 volumio sudo[12198]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 13:54:12 volumio volumio[1314]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 31 13:54:12 volumio volumio[1314]: info: MPD Permissions set May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 13:54:12 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber May 31 13:54:12 volumio systemd[1]: mpd.service: Deactivated successfully. May 31 13:54:12 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. May 31 13:54:12 volumio systemd[1]: mpd.socket: Deactivated successfully. May 31 13:54:12 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. May 31 13:54:12 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... May 31 13:54:12 volumio volumio[1314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 13:54:12 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. May 31 13:54:12 volumio volumio[1314]: info: Starting Shairport Sync May 31 13:54:12 volumio systemd[1]: Starting mpd.service - Music Player Daemon... May 31 13:54:12 volumio sudo[12216]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 31 13:54:12 volumio sudo[12216]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 13:54:12 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... May 31 13:54:12 volumio systemd[1]: shairport-sync.service: Deactivated successfully. May 31 13:54:12 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 31 13:54:12 volumio systemd[1]: shairport-sync.service: Consumed 2.413s CPU time. May 31 13:54:12 volumio sudo[12214]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 31 13:54:12 volumio sudo[12214]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) May 31 13:54:12 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 31 13:54:12 volumio sudo[12214]: pam_unix(sudo:session): session closed for user root May 31 13:54:12 volumio sudo[12216]: pam_unix(sudo:session): session closed for user root May 31 13:54:12 volumio volumio[1314]: info: Shairport-Sync Started May 31 13:54:13 volumio mpd[12220]: 2026-05-31T13:54:13 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 31 13:54:13 volumio systemd[1]: Started mpd.service - Music Player Daemon. May 31 13:54:13 volumio sudo[12198]: pam_unix(sudo:session): session closed for user root May 31 13:54:13 volumio volumio[1314]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 31 13:54:13 volumio volumio[1314]: TypeError: Cannot read properties of null (reading 'printToastMessage') May 31 13:54:13 volumio volumio[1314]: at /volumio/app/index.js:1214:32 May 31 13:54:13 volumio volumio[1314]: at fastMap (/volumio/node_modules/fast.js/array/map.js:21:17) May 31 13:54:13 volumio volumio[1314]: at Function.fastMap [as map] (/volumio/node_modules/fast.js/map.js:18:12) May 31 13:54:13 volumio volumio[1314]: at CoreCommandRouter.pushToastMessage (/volumio/app/index.js:1212:13) May 31 13:54:13 volumio volumio[1314]: at /volumio/app/plugins/music_service/mpd/index.js:811:30 May 31 13:54:13 volumio volumio[1314]: at /volumio/app/plugins/music_service/mpd/index.js:955:9 May 31 13:54:13 volumio volumio[1314]: at ChildProcess.exithandler (node:child_process:413:7) May 31 13:54:13 volumio volumio[1314]: at ChildProcess.emit (node:events:514:28) May 31 13:54:13 volumio volumio[1314]: at maybeClose (node:internal/child_process:1105:16) May 31 13:54:13 volumio volumio[1314]: at ChildProcess._handle.onexit (node:internal/child_process:305:5) May 31 13:54:13 volumio volumio[1314]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 31 13:54:13 volumio sudo[12253]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-05-31 13:53' May 31 13:54:13 volumio sudo[12253]: 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"