Mar 15 10:21:04 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:21:07 rpi5-bw volumio[1528]: warn: FusionDsp - Monitor WebSocket not open, skipping commands Mar 15 10:21:09 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:21:14 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:21:19 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 15 10:21:19 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 15 10:21:19 rpi5-bw volumio[1528]: info: Discovery: Getting this device information Mar 15 10:21:19 rpi5-bw volumio[1528]: info: CoreCommandRouter::volumioGetState Mar 15 10:21:19 rpi5-bw volumio[1528]: info: CorePlayQueue::getTrack 0 Mar 15 10:21:19 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 15 10:21:19 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:21:24 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:21:29 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:21:34 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:21:37 rpi5-bw volumio[1528]: warn: FusionDsp - Monitor WebSocket not open, skipping commands Mar 15 10:21:39 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:21:44 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:21:49 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 15 10:21:49 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 15 10:21:49 rpi5-bw volumio[1528]: info: Discovery: Getting this device information Mar 15 10:21:49 rpi5-bw volumio[1528]: info: CoreCommandRouter::volumioGetState Mar 15 10:21:49 rpi5-bw volumio[1528]: info: CorePlayQueue::getTrack 0 Mar 15 10:21:49 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 15 10:21:49 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:21:54 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:21:59 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:22:04 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:22:07 rpi5-bw volumio[1528]: warn: FusionDsp - Monitor WebSocket not open, skipping commands Mar 15 10:22:09 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:22:14 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 15 10:22:14 rpi5-bw volumio[1528]: info: Received Get System Info Mar 15 10:22:14 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 15 10:22:14 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 15 10:22:14 rpi5-bw volumio[1528]: info: Discovery: Getting this device information Mar 15 10:22:14 rpi5-bw volumio[1528]: info: CoreCommandRouter::volumioGetState Mar 15 10:22:14 rpi5-bw volumio[1528]: info: CorePlayQueue::getTrack 0 Mar 15 10:22:14 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 15 10:22:14 rpi5-bw kernel: drm-rp1-dsi 1f00130000.dsi: [drm] rp1dsi: Command time (outvact): 33 Mar 15 10:22:14 rpi5-bw kernel: drm-rp1-dsi 1f00130000.dsi: [drm] rp1dsi: Nominal Byte clock 90000000 DPI clock 30000000 (parent rate 90000000) Mar 15 10:22:14 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:22:17 rpi5-bw volumio[1528]: info: CoreCommandRouter::volumioPlay Mar 15 10:22:17 rpi5-bw volumio[1528]: info: CoreStateMachine::play index undefined Mar 15 10:22:17 rpi5-bw volumio[1528]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 15 10:22:17 rpi5-bw volumio[1528]: info: CorePlayQueue::getTrack 0 Mar 15 10:22:17 rpi5-bw volumio[1528]: info: CoreStateMachine::startPlaybackTimer Mar 15 10:22:17 rpi5-bw volumio[1528]: info: CorePlayQueue::getTrack 0 Mar 15 10:22:17 rpi5-bw volumio[1528]: verbose: ControllerMpd::clearAddPlayTracks NAS/QNAP/Cappella/(2006) - Greatest Hits/0116 - Cappella - U Got 2 Let The Music (Dj Shogs Remix).flac Mar 15 10:22:17 rpi5-bw volumio[1528]: verbose: ControllerMpd::sendMpdCommand stop Mar 15 10:22:17 rpi5-bw volumio[1528]: info: sendMpdCommand stop took 1 milliseconds Mar 15 10:22:17 rpi5-bw volumio[1528]: verbose: ControllerMpd::sendMpdCommand clear Mar 15 10:22:17 rpi5-bw volumio[1528]: info: Mar 15 10:22:17 rpi5-bw volumio[1528]: ---------------------------- MPD announces system playlist update Mar 15 10:22:17 rpi5-bw volumio[1528]: info: Ignoring MPD Status Update Mar 15 10:22:17 rpi5-bw volumio[1528]: info: sendMpdCommand clear took 0 milliseconds Mar 15 10:22:17 rpi5-bw volumio[1528]: verbose: ControllerMpd::sendMpdCommand add "NAS/QNAP/Cappella/(2006) - Greatest Hits/0116 - Cappella - U Got 2 Let The Music (Dj Shogs Remix).flac" Mar 15 10:22:17 rpi5-bw volumio[1528]: error: updateQueue error: null Mar 15 10:22:17 rpi5-bw volumio[1528]: info: ------------------------------ 1ms Mar 15 10:22:17 rpi5-bw volumio[1528]: info: Mar 15 10:22:17 rpi5-bw volumio[1528]: ---------------------------- MPD announces system playlist update Mar 15 10:22:17 rpi5-bw volumio[1528]: info: Ignoring MPD Status Update Mar 15 10:22:17 rpi5-bw volumio[1528]: info: sendMpdCommand add "NAS/QNAP/Cappella/(2006) - Greatest Hits/0116 - Cappella - U Got 2 Let The Music (Dj Shogs Remix).flac" took 1 milliseconds Mar 15 10:22:17 rpi5-bw volumio[1528]: verbose: ControllerMpd::sendMpdCommand play Mar 15 10:22:17 rpi5-bw volumio[1528]: info: ------------------------------ 1ms Mar 15 10:22:17 rpi5-bw volumio[1528]: info: sendMpdCommand play took 0 milliseconds Mar 15 10:22:17 rpi5-bw volumio[1528]: info: Mar 15 10:22:17 rpi5-bw volumio[1528]: ---------------------------- MPD announces state update: player Mar 15 10:22:17 rpi5-bw volumio[1528]: info: ControllerMpd::getState Mar 15 10:22:17 rpi5-bw volumio[1528]: verbose: ControllerMpd::sendMpdCommand status Mar 15 10:22:17 rpi5-bw volumio[1528]: info: FusionDsp - ---- read samplerate, raw: 48000,S32_LE,2,32 Mar 15 10:22:17 rpi5-bw volumio[1528]: info: FusionDsp - ---- read samplerate from file: 48000 Mar 15 10:22:17 rpi5-bw volumio[1528]: info: camilladsp stopping service pid 2583... Mar 15 10:22:18 rpi5-bw volumio[1528]: grep: /proc/2583/cmdline: binary file matches Mar 15 10:22:18 rpi5-bw volumio[1528]: grep: /proc/2583/cmdline: binary file matches Mar 15 10:22:18 rpi5-bw volumio[1528]: grep: /proc/2583/cmdline: binary file matches Mar 15 10:22:18 rpi5-bw volumio[1528]: info: camilladsp service terminated, instance 1 Mar 15 10:22:18 rpi5-bw volumio[1528]: info: FusionDsp - If filter freq >samplerate/2 then disable it Mar 15 10:22:18 rpi5-bw volumio[1528]: info: camilladsp service started and running in background, instance 1 Mar 15 10:22:18 rpi5-bw volumio[1528]: info: FusionDsp - ---- read samplerate, raw: 48000,S32_LE,2,32 Mar 15 10:22:18 rpi5-bw volumio[1528]: info: FusionDsp - ---- read samplerate from file: 48000 Mar 15 10:22:18 rpi5-bw volumio[1528]: info: FusionDsp - If filter freq >samplerate/2 then disable it Mar 15 10:22:18 rpi5-bw volumio[1528]: info: Mar 15 10:22:18 rpi5-bw volumio[1528]: ---------------------------- MPD announces state update: player Mar 15 10:22:18 rpi5-bw volumio[1528]: info: sendMpdCommand status took 333 milliseconds Mar 15 10:22:18 rpi5-bw volumio[1528]: info: ControllerMpd::getState Mar 15 10:22:18 rpi5-bw volumio[1528]: verbose: ControllerMpd::sendMpdCommand status Mar 15 10:22:18 rpi5-bw volumio[1528]: verbose: ControllerMpd::parseState Mar 15 10:22:18 rpi5-bw volumio[1528]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 15 10:22:18 rpi5-bw volumio[1528]: info: sendMpdCommand status took 2 milliseconds Mar 15 10:22:18 rpi5-bw volumio[1528]: info: sendMpdCommand playlistinfo took 1 milliseconds Mar 15 10:22:18 rpi5-bw volumio[1528]: verbose: ControllerMpd::parseState Mar 15 10:22:18 rpi5-bw volumio[1528]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 15 10:22:18 rpi5-bw volumio[1528]: verbose: ControllerMpd::parseTrackInfo Mar 15 10:22:18 rpi5-bw volumio[1528]: info: ControllerMpd::pushState Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CoreCommandRouter::servicePushState Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CorePlayQueue::getTrack 0 Mar 15 10:22:18 rpi5-bw volumio[1528]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":457,"samplerate":"48 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"U Got 2 Let The Music (Dj Shogs Remix)","artist":"Cappella","album":"Greatest Hits","uri":"NAS/QNAP/Cappella/(2006) - Greatest Hits/0116 - Cappella - U Got 2 Let The Music (Dj Shogs Remix).flac","trackType":"flac"} Mar 15 10:22:18 rpi5-bw volumio[1528]: verbose: CURRENT POSITION 0 Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CoreStateMachine::syncState stateService play Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CoreStateMachine::syncState currentStatus stop Mar 15 10:22:18 rpi5-bw volumio[1528]: info: ------------------------------ 341ms Mar 15 10:22:18 rpi5-bw volumio[1528]: error: FusionDsp - Reload WebSocket error: [object Object] Mar 15 10:22:18 rpi5-bw volumio[1528]: info: sendMpdCommand playlistinfo took 8 milliseconds Mar 15 10:22:18 rpi5-bw volumio[1528]: verbose: ControllerMpd::parseTrackInfo Mar 15 10:22:18 rpi5-bw volumio[1528]: info: ControllerMpd::pushState Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CoreCommandRouter::servicePushState Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CorePlayQueue::getTrack 0 Mar 15 10:22:18 rpi5-bw volumio[1528]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1600,"duration":457,"samplerate":"48 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1007 Kbps","isStreaming":false,"title":"U Got 2 Let The Music (Dj Shogs Remix)","artist":"Cappella","album":"Greatest Hits","uri":"NAS/QNAP/Cappella/(2006) - Greatest Hits/0116 - Cappella - U Got 2 Let The Music (Dj Shogs Remix).flac","trackType":"flac"} Mar 15 10:22:18 rpi5-bw volumio[1528]: verbose: CURRENT POSITION 0 Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CoreStateMachine::syncState stateService play Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CoreStateMachine::syncState currentStatus play Mar 15 10:22:18 rpi5-bw volumio[1528]: info: Received an update from plugin. extracting info from payload Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CoreStateMachine::pushState Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CorePlayQueue::getTrack 0 Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CoreCommandRouter::volumioPushState Mar 15 10:22:18 rpi5-bw volumio[1528]: info: MRS: Pushing multiroomSync output update for this device Mar 15 10:22:18 rpi5-bw volumio[1528]: info: MRS: Pushing multiroomSync output Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CoreStateMachine::pushState Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CorePlayQueue::getTrack 0 Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CoreCommandRouter::volumioPushState Mar 15 10:22:18 rpi5-bw volumio[1528]: info: MRS: Pushing multiroomSync output update for this device Mar 15 10:22:18 rpi5-bw volumio[1528]: info: MRS: Pushing multiroomSync output Mar 15 10:22:18 rpi5-bw volumio[1528]: info: ------------------------------ 28ms Mar 15 10:22:18 rpi5-bw volumio[1528]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 15 10:22:18 rpi5-bw volumio[1528]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 15 10:22:18 rpi5-bw volumio[1528]: info: touch_display: Setting screensaver timeout to 0 seconds. Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 15 10:22:18 rpi5-bw volumio[1528]: info: Discovery: Getting this device information Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CoreCommandRouter::volumioGetState Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CorePlayQueue::getTrack 0 Mar 15 10:22:18 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 15 10:22:19 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:22:24 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:22:29 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:22:34 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:22:39 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 15 10:22:39 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 15 10:22:39 rpi5-bw volumio[1528]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 15 10:22:39 rpi5-bw volumio[1528]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 15 10:22:39 rpi5-bw volumio[1528]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 15 10:22:39 rpi5-bw volumio[1528]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 15 10:22:39 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:22:44 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 4 Transport: polling Total Clients: 33 Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Starting Uninstall of plugin user_interface - peppy_screensaver Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Uninstalling plugin peppy_screensaver Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreStateMachine::stop Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreStateMachine::stPlaybackTimer Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreStateMachine::updateTrackBlock Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CorePlayQueue::getTrackBlock Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreStateMachine::pushState Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CorePlayQueue::getTrack 0 Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::volumioPushState Mar 15 10:22:46 rpi5-bw volumio[1528]: info: MRS: Pushing multiroomSync output update for this device Mar 15 10:22:46 rpi5-bw volumio[1528]: info: MRS: Pushing multiroomSync output Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreStateMachine::serviceStop Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CorePlayQueue::getTrack 0 Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::serviceStop Mar 15 10:22:46 rpi5-bw volumio[1528]: info: ControllerMpd::stop Mar 15 10:22:46 rpi5-bw volumio[1528]: verbose: ControllerMpd::sendMpdCommand stop Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Disabling plugin peppy_screensaver Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Preparing to generate the ALSA configuration file Mar 15 10:22:46 rpi5-bw volumio[1528]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 15 10:22:46 rpi5-bw volumio[1528]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Mar 15 10:22:46 rpi5-bw volumio[1528]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Reading ALSA contributions from plugins. Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Asound.conf file written Mar 15 10:22:46 rpi5-bw sudo[4684]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Mar 15 10:22:46 rpi5-bw sudo[4684]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 15 10:22:46 rpi5-bw sudo[4684]: pam_unix(sudo:session): session closed for user root Mar 15 10:22:46 rpi5-bw volumio[1528]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Mar 15 10:22:46 rpi5-bw volumio[1528]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:Max Overclock PLL:0' : Device or resource busy Mar 15 10:22:46 rpi5-bw volumio[1528]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:Max Overclock DSP:0' : Device or resource busy Mar 15 10:22:46 rpi5-bw volumio[1528]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:Max Overclock DAC:0' : Device or resource busy Mar 15 10:22:46 rpi5-bw volumio[1528]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Mar 15 10:22:46 rpi5-bw volumio[1528]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Mar 15 10:22:46 rpi5-bw volumio[1528]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:7 use case configuration -2 Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Output device has changed, restarting MPD Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Output device has changed, restarting Shairport Sync Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 15 10:22:46 rpi5-bw sudo[4692]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 15 10:22:46 rpi5-bw sudo[4692]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 15 10:22:46 rpi5-bw sudo[4692]: pam_unix(sudo:session): session closed for user root Mar 15 10:22:46 rpi5-bw sudo[4696]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 15 10:22:46 rpi5-bw sudo[4696]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 15 10:22:46 rpi5-bw volumio[1528]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw systemd[1]: Stopping mpd.service - Music Player Daemon... Mar 15 10:22:46 rpi5-bw vtcs[2492]: [2025-03-15 10:22:46.562] [tisoc] [error] [SpkconServer.cpp:375] recv error. socket disconnected Mar 15 10:22:46 rpi5-bw vtcs[2492]: [2025-03-15 10:22:46.562] [tisoc] [warning] [SessionManagerImpl.cpp:240] Illegal State: IDLE Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Checking if uninstall.sh is present Mar 15 10:22:46 rpi5-bw sudo[4704]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Mar 15 10:22:46 rpi5-bw sudo[4704]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Executing uninstall.sh Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Mar 15 10:22:46 rpi5-bw volumio[1528]: ---------------------------- MPD announces state update: player Mar 15 10:22:46 rpi5-bw volumio[1528]: info: sendMpdCommand stop took 118 milliseconds Mar 15 10:22:46 rpi5-bw volumio[1528]: info: ControllerMpd::getState Mar 15 10:22:46 rpi5-bw volumio[1528]: verbose: ControllerMpd::sendMpdCommand status Mar 15 10:22:46 rpi5-bw volumio[1528]: info: peppy_screensaver: mpd template already unmounted Mar 15 10:22:46 rpi5-bw volumio[1528]: ------------------------------------ BT MESSAGE: BT STATUS: running Mar 15 10:22:46 rpi5-bw volumio[1528]: error: Failed to parse min max audio card capabilities, sending default vales: TypeError: Cannot read properties of undefined (reading 'split') Mar 15 10:22:46 rpi5-bw sudo[4706]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Mar 15 10:22:46 rpi5-bw volumio[1528]: info: MPD Permissions set Mar 15 10:22:46 rpi5-bw volumio[1528]: info: touch_display: Setting screensaver timeout to 120 seconds. Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw sudo[4710]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/user_interface/peppy_screensaver/uninstall.sh Mar 15 10:22:46 rpi5-bw systemd[1]: vtcs.service: Deactivated successfully. Mar 15 10:22:46 rpi5-bw sudo[4710]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 15 10:22:46 rpi5-bw systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Mar 15 10:22:46 rpi5-bw sudo[4706]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw sudo[4704]: pam_unix(sudo:session): session closed for user root Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: spop , initializeLibrespotDaemon Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Creating Spotify config file Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: ------------------------------------ BT MESSAGE: BT STATUS: running Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Starting Shairport Sync Mar 15 10:22:46 rpi5-bw sudo[4706]: pam_unix(sudo:session): session closed for user root Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Spotify config file written Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Preparing to generate the ALSA configuration file Mar 15 10:22:46 rpi5-bw sudo[4739]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 15 10:22:46 rpi5-bw sudo[4739]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 15 10:22:46 rpi5-bw volumio[1528]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Mar 15 10:22:46 rpi5-bw volumio[1528]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Reading ALSA contributions from plugins. Mar 15 10:22:46 rpi5-bw sudo[4740]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 15 10:22:46 rpi5-bw sudo[4740]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Asound.conf file unchanged, so no further update is needed Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Output device has changed, restarting MPD Mar 15 10:22:46 rpi5-bw systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 15 10:22:46 rpi5-bw systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 15 10:22:46 rpi5-bw systemd[1]: shairport-sync.service: Deactivated successfully. Mar 15 10:22:46 rpi5-bw systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 15 10:22:46 rpi5-bw systemd[1]: shairport-sync.service: Consumed 2.574s CPU time. Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Output device has changed, restarting Shairport Sync Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 15 10:22:46 rpi5-bw sudo[4745]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 15 10:22:46 rpi5-bw sudo[4745]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 15 10:22:46 rpi5-bw volumio[1528]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw sudo[4747]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 15 10:22:46 rpi5-bw systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 15 10:22:46 rpi5-bw sudo[4747]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 15 10:22:46 rpi5-bw sudo[4745]: pam_unix(sudo:session): session closed for user root Mar 15 10:22:46 rpi5-bw sudo[4739]: pam_unix(sudo:session): session closed for user root Mar 15 10:22:46 rpi5-bw systemd[1]: mpd.service: Deactivated successfully. Mar 15 10:22:46 rpi5-bw volumio[1528]: error: MPD error: Error: read ECONNRESET Mar 15 10:22:46 rpi5-bw volumio[1528]: ------------------------------------ BT MESSAGE: BT STATUS: running Mar 15 10:22:46 rpi5-bw volumio[1528]: ------------------------------------ BT MESSAGE: BT STATUS: running Mar 15 10:22:46 rpi5-bw volumio[1528]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Connection to go-librespot Websocket closed Mar 15 10:22:46 rpi5-bw volumio[1528]: error: Failed to parse min max audio card capabilities, sending default vales: TypeError: Cannot read properties of undefined (reading 'split') Mar 15 10:22:46 rpi5-bw sudo[4758]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Mar 15 10:22:46 rpi5-bw systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 15 10:22:46 rpi5-bw volumio[1528]: info: MPD Permissions set Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Shairport-Sync Started Mar 15 10:22:46 rpi5-bw sudo[4758]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 15 10:22:46 rpi5-bw systemd[1]: mpd.service: Consumed 1.144s CPU time. Mar 15 10:22:46 rpi5-bw sudo[4761]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Mar 15 10:22:46 rpi5-bw systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 15 10:22:46 rpi5-bw sudo[4761]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 15 10:22:46 rpi5-bw systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 15 10:22:46 rpi5-bw volumio[1528]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Mar 15 10:22:46 rpi5-bw volumio[1528]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Mar 15 10:22:46 rpi5-bw volumio[1528]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Mar 15 10:22:46 rpi5-bw systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 15 10:22:46 rpi5-bw systemd[1]: mpd.socket: Deactivated successfully. Mar 15 10:22:46 rpi5-bw systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 15 10:22:46 rpi5-bw systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 15 10:22:46 rpi5-bw sudo[4740]: pam_unix(sudo:session): session closed for user root Mar 15 10:22:46 rpi5-bw systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 15 10:22:46 rpi5-bw systemd[1]: Starting mpd.service - Music Player Daemon... Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Starting Shairport Sync Mar 15 10:22:46 rpi5-bw go-librespot[4769]: Librespot-go daemon starting... Mar 15 10:22:46 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:46+01:00" level=info msg="generated new device id: 8f80ae87c28013669d793d2e1df069062f6092ac" Mar 15 10:22:46 rpi5-bw volumio[1528]: ------------------------------------ BT MESSAGE: BT STATUS: running Mar 15 10:22:46 rpi5-bw sudo[4758]: pam_unix(sudo:session): session closed for user root Mar 15 10:22:46 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:46+01:00" level=debug msg="stored credentials found for z4ujt0w8jsm3yt93kz6hrseoy" Mar 15 10:22:46 rpi5-bw sudo[4761]: pam_unix(sudo:session): session closed for user root Mar 15 10:22:46 rpi5-bw sudo[4792]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 15 10:22:46 rpi5-bw sudo[4792]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 15 10:22:46 rpi5-bw systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 15 10:22:46 rpi5-bw systemd[1]: shairport-sync.service: Deactivated successfully. Mar 15 10:22:46 rpi5-bw systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 15 10:22:46 rpi5-bw volumio[1528]: ------------------------------------ BT MESSAGE: BT STATUS: running Mar 15 10:22:46 rpi5-bw volumio[1528]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Mar 15 10:22:46 rpi5-bw sudo[4782]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 15 10:22:46 rpi5-bw sudo[4782]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 15 10:22:46 rpi5-bw systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 15 10:22:46 rpi5-bw sudo[4782]: pam_unix(sudo:session): session closed for user root Mar 15 10:22:46 rpi5-bw sudo[4792]: pam_unix(sudo:session): session closed for user root Mar 15 10:22:46 rpi5-bw volumio[1528]: info: Shairport-Sync Started Mar 15 10:22:46 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:46+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 15 10:22:46 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:46+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 15 10:22:46 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:46+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 15 10:22:46 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:46+01:00" level=debug msg="zeroconf server listening on port 35335" Mar 15 10:22:46 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 34 Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CALLMETHOD: music_service mpd createMPDFile Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: mpd , createMPDFile Mar 15 10:22:46 rpi5-bw volumio[1528]: error: Failed callmethod call: TypeError: callback is not a function Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 15 10:22:46 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:47 rpi5-bw sudo[4822]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 15 10:22:47 rpi5-bw sudo[4822]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 15 10:22:47 rpi5-bw sudo[4822]: pam_unix(sudo:session): session closed for user root Mar 15 10:22:47 rpi5-bw volumio[1528]: info: MPD Permissions set Mar 15 10:22:47 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:47+01:00" level=debug msg="obtained new client token: AADd4lEdNlR4Uz3N5LCJJ5DVTxJA6EGFLpfI3wrfjn0ur9VDslKU5N8CM+zvo3iM3UCVn/BUR7ICQA+oWualVWhTSXV0UP56k0Z7LOSpkpj9mgu/DO8+EaDCV6O2IKnzCIwuY5AwTFkybmJWSco9ufwBlbKmG5wHTPyp1qV0seG9pKDNqmKW3hxzrjS3VIu42So9oyBbWA0oUToSYMXvjlZi9ICboX5dcslo8ApPLPr2paGFHcaglzajYKz9p/g=" Mar 15 10:22:47 rpi5-bw ntpd[1222]: PROTO: 178.215.228.24 unlink local addr 192.168.1.168 -> Mar 15 10:22:47 rpi5-bw volumio[1528]: info: CALLMETHOD: music_service airplay_emulation outputDeviceCallback Mar 15 10:22:47 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , outputDeviceCallback Mar 15 10:22:47 rpi5-bw volumio[1528]: info: Output device has changed, restarting Shairport Sync Mar 15 10:22:47 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:47 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 15 10:22:47 rpi5-bw volumio[1528]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 15 10:22:47 rpi5-bw volumio[1528]: info: Starting Shairport Sync Mar 15 10:22:47 rpi5-bw sudo[4832]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 15 10:22:47 rpi5-bw sudo[4832]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 15 10:22:47 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:47+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Mar 15 10:22:47 rpi5-bw systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 15 10:22:47 rpi5-bw systemd[1]: shairport-sync.service: Deactivated successfully. Mar 15 10:22:47 rpi5-bw volumio[1528]: ------------------------------------ BT MESSAGE: BT STATUS: running Mar 15 10:22:47 rpi5-bw volumio[1528]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Mar 15 10:22:47 rpi5-bw systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 15 10:22:47 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:47+01:00" level=debug msg="completed keyexchange" Mar 15 10:22:47 rpi5-bw systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 15 10:22:47 rpi5-bw sudo[4832]: pam_unix(sudo:session): session closed for user root Mar 15 10:22:47 rpi5-bw volumio[1528]: info: Shairport-Sync Started Mar 15 10:22:47 rpi5-bw mpd[4799]: Mar 15 10:22 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 15 10:22:47 rpi5-bw systemd[1]: Started mpd.service - Music Player Daemon. Mar 15 10:22:47 rpi5-bw sudo[4747]: pam_unix(sudo:session): session closed for user root Mar 15 10:22:47 rpi5-bw sudo[4696]: pam_unix(sudo:session): session closed for user root Mar 15 10:22:47 rpi5-bw volumio[1528]: error: MPD error: The expression evaluated to a falsy value: Mar 15 10:22:47 rpi5-bw volumio[1528]: assert.ok(self.idling) Mar 15 10:22:47 rpi5-bw volumio[1528]: error: The expression evaluated to a falsy value: Mar 15 10:22:47 rpi5-bw volumio[1528]: assert.ok(self.idling) Mar 15 10:22:47 rpi5-bw volumio[1528]: error: updateQueue error: null Mar 15 10:22:47 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:47+01:00" level=debug msg="completed challenge" Mar 15 10:22:48 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:48+01:00" level=debug msg="authenticated as z4ujt0w8jsm3yt93kz6hrseoy" Mar 15 10:22:48 rpi5-bw volumio[1528]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 34 Mar 15 10:22:48 rpi5-bw volumio[1528]: info: CALLMETHOD: user_interface peppy_screensaver restoreAsoundConfig Mar 15 10:22:48 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: peppy_screensaver , restoreAsoundConfig Mar 15 10:22:48 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:48+01:00" level=debug msg="authenticated as z4ujt0w8jsm3yt93kz6hrseoy" Mar 15 10:22:48 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:48+01:00" level=debug msg="dealer connection opened" Mar 15 10:22:48 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:48+01:00" level=debug msg="initializing zeroconf session, username: z4ujt0w8jsm3yt93kz6hrseoy" Mar 15 10:22:48 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:48+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 15 10:22:48 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:48+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 15 10:22:48 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:48+01:00" level=debug msg="autoplay enabled: false" Mar 15 10:22:48 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:48+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 15 10:22:48 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:48+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 15 10:22:48 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:48+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 15 10:22:48 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 15 10:22:48 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 15 10:22:48 rpi5-bw volumio[1528]: info: Discovery: Getting this device information Mar 15 10:22:48 rpi5-bw volumio[1528]: info: CoreCommandRouter::volumioGetState Mar 15 10:22:48 rpi5-bw volumio[1528]: info: CorePlayQueue::getTrack 0 Mar 15 10:22:48 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 15 10:22:48 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:48+01:00" level=debug msg="received connection id: ZjFiYTUxNWItMjMxZi00YTM4LTg0MmQtNmI0N2U3ZmEwNjczK2RlYWxlcit0Y3A6Ly8wYWNhNTgxNi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArNDlDNUE4RjlGN0E0QkNFQjMxRUU0NzRFRUU0MDU0RDRFNDIwRkM2RjNCQkJCNTUzNjI3MjlENTU3NEE5MUI0RQ==" Mar 15 10:22:48 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:48+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 15 10:22:48 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:48 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 15 10:22:48 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , disableSoftMixer Mar 15 10:22:48 rpi5-bw volumio[1528]: info: Disable softmixer device for audio device Mar 15 10:22:48 rpi5-bw volumio[1528]: info: Cannot delete /data/configuration/audio_interface/alsa_controller/asound/softvolume-postVolume.conf: Error: ENOENT: no such file or directory, unlink '/data/configuration/audio_interface/alsa_controller/asound/softvolume.postVolume.conf' Mar 15 10:22:49 rpi5-bw ntpd[1222]: PROTO: 162.159.200.1 unlink local addr 192.168.1.168 -> Mar 15 10:22:49 rpi5-bw ntpd[1222]: PROTO: 178.239.19.58 unlink local addr 192.168.1.168 -> Mar 15 10:22:49 rpi5-bw sudo[4710]: pam_unix(sudo:session): session closed for user root Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Uninstall script completed Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Removing plugin peppy_screensaver from configuration Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Successfully removed peppy_screensaver configuration files Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Plugin folders cleanup Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Scanning into folder /volumio/app/plugins/ Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Scanning category audio_interface Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Scanning category miscellanea Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Scanning category music_service Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Scanning category plugins.json Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Scanning category system_controller Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Scanning category user_interface Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Scanning into folder /data/plugins/ Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Scanning category audio_interface Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Scanning category music_service Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Scanning category system_hardware Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Scanning category user_interface Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Cleaning folder for peppy_screensaver Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Plugin folders cleanup completed Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 15 10:22:49 rpi5-bw volumio[1528]: info: [{"prettyName":"FusionDsp","name":"fusiondsp","category":"audio_interface","version":"2.0.65","icon":"fa-sliders fa-rotate-90","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"80s80s Radio","name":"80s80s","category":"music_service","version":"2.0.4","icon":"fa-headphones","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"MotherEarthRadio","name":"motherearthradio","category":"music_service","version":"1.3.0","icon":"fa-lightbulb-o","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Radio Paradise","name":"radio_paradise","category":"music_service","version":"2.0.12","icon":"fa-headphones","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Spotify","name":"spop","category":"music_service","version":"4.1.1","icon":"fa-spotify","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Rotary Encoder II","name":"rotaryencoder2","category":"system_hardware","version":"1.1.1","icon":"fa-circle-o-notch","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"System information","name":"Systeminfo","category":"user_interface","version":"3.0.7","icon":"fa-info-circle","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Randomizer","name":"randomizer","category":"user_interface","version":"4.1.2","icon":"fa-random","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Touch Display","name":"touch_display","category":"user_interface","version":"3.5.2","icon":"fa-hand-pointer-o","isManuallyInstalled":false,"enabled":true,"active":true}] Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 15 10:22:49 rpi5-bw volumio[1528]: info: TidalConnect service stoped! Mar 15 10:22:49 rpi5-bw volumio[1528]: info: TidalConnect service stoped! Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect Mar 15 10:22:49 rpi5-bw sudo[4894]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Mar 15 10:22:49 rpi5-bw sudo[4894]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 15 10:22:49 rpi5-bw systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Mar 15 10:22:49 rpi5-bw sudo[4894]: pam_unix(sudo:session): session closed for user root Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Initializing connection to go-librespot Websocket Mar 15 10:22:49 rpi5-bw go-librespot[4784]: time="2025-03-15T10:22:49+01:00" level=debug msg="new websocket client" Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Connection to go-librespot Websocket established Mar 15 10:22:49 rpi5-bw volumio[1528]: info: go-librespot daemon successfully initialized Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Executing endpoint tc_getconfig Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Mar 15 10:22:49 rpi5-bw vtcs[4897]: STARTING TidalConnect services, version: 1.5.0.45 Mar 15 10:22:49 rpi5-bw volumio[1528]: info: TidalConnect service stoped! Mar 15 10:22:49 rpi5-bw volumio[1528]: info: TidalConnect service stoped! Mar 15 10:22:49 rpi5-bw vtcs[4897]: STARTED TidalConnect services. Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Executing endpoint tc_connect Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Connecting to TidalConnect Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CoreCommandRouter::servicePushState Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CoreStateMachine::pushState Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CorePlayQueue::getTrack 0 Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CoreCommandRouter::volumioPushState Mar 15 10:22:49 rpi5-bw volumio[1528]: info: MRS: Pushing multiroomSync output update for this device Mar 15 10:22:49 rpi5-bw volumio[1528]: info: MRS: Pushing multiroomSync output Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CorePlayQueue::getTrack 0 Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current mpd Received tidalconnect Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CoreCommandRouter::servicePushState Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CoreStateMachine::pushState Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CorePlayQueue::getTrack 0 Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CoreCommandRouter::volumioPushState Mar 15 10:22:49 rpi5-bw volumio[1528]: info: MRS: Pushing multiroomSync output update for this device Mar 15 10:22:49 rpi5-bw volumio[1528]: info: MRS: Pushing multiroomSync output Mar 15 10:22:49 rpi5-bw volumio[1528]: info: CorePlayQueue::getTrack 0 Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current mpd Received tidalconnect Mar 15 10:22:49 rpi5-bw volumio[1528]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 15 10:22:49 rpi5-bw volumio[1528]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Mar 15 10:22:49 rpi5-bw volumio[1528]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect Mar 15 10:22:49 rpi5-bw volumio[1528]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 15 10:22:49 rpi5-bw volumio[1528]: Error: ENOENT: no such file or directory, unlink '/tmp/oVqlWHZuqY8H7ZcVUzsGnfuwXOnofM130s8ytJyFoIH0HMKcTVuQpLxjcj96PqWKq7We7kJFTc4gS4YdzpeKD3MM7Zkaecc5CowX' Mar 15 10:22:49 rpi5-bw volumio[1528]: at Object.unlinkSync (node:fs:1899:3) Mar 15 10:22:49 rpi5-bw volumio[1528]: at ControllerTidalconnect.deleteCertificate (/myvolumio/plugins/music_service/tidalconnect/tidalconnect_real:1:11238) Mar 15 10:22:49 rpi5-bw volumio[1528]: at TidalConnectClient. (/myvolumio/plugins/music_service/tidalconnect/tidalconnect_real:1:2774) Mar 15 10:22:49 rpi5-bw volumio[1528]: at TidalConnectClient.emit (node:events:514:28) Mar 15 10:22:49 rpi5-bw volumio[1528]: at TidalConnectClient.parseData (/myvolumio/plugins/music_service/tidalconnect/tidalconnect_real:1:44661) Mar 15 10:22:49 rpi5-bw volumio[1528]: at /myvolumio/plugins/music_service/tidalconnect/tidalconnect_real:1:41631 Mar 15 10:22:49 rpi5-bw volumio[1528]: at Array.forEach () Mar 15 10:22:49 rpi5-bw volumio[1528]: at Socket. (/myvolumio/plugins/music_service/tidalconnect/tidalconnect_real:1:41509) Mar 15 10:22:49 rpi5-bw volumio[1528]: at Socket.emit (node:events:514:28) Mar 15 10:22:49 rpi5-bw volumio[1528]: at addChunk (node:internal/streams/readable:343:12) Mar 15 10:22:49 rpi5-bw volumio[1528]: at readableAddChunk (node:internal/streams/readable:316:9) Mar 15 10:22:49 rpi5-bw volumio[1528]: at Readable.push (node:internal/streams/readable:253:10) Mar 15 10:22:49 rpi5-bw volumio[1528]: at Pipe.onStreamRead (node:internal/stream_base_commons:190:23) { Mar 15 10:22:49 rpi5-bw volumio[1528]: errno: -2, Mar 15 10:22:49 rpi5-bw volumio[1528]: syscall: 'unlink', Mar 15 10:22:49 rpi5-bw volumio[1528]: code: 'ENOENT', Mar 15 10:22:49 rpi5-bw volumio[1528]: path: '/tmp/oVqlWHZuqY8H7ZcVUzsGnfuwXOnofM130s8ytJyFoIH0HMKcTVuQpLxjcj96PqWKq7We7kJFTc4gS4YdzpeKD3MM7Zkaecc5CowX' Mar 15 10:22:49 rpi5-bw volumio[1528]: } Mar 15 10:22:49 rpi5-bw volumio[1528]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 15 10:22:49 rpi5-bw sudo[4935]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-03-15 10:21' Mar 15 10:22:49 rpi5-bw sudo[4935]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="30b940f30730969a1c56b277277ec58998d851c0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="a01a833dd28483f88cb390596f5090b7187992af" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed Mar 12 09:14:02 UTC 2025" VOLUMIO_VERSION="0.044" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5278259823a3b628f3689058d8a8fc6f"