-- Logs begin at Thu 2019-02-14 10:11:58 GMT, end at Sat 2026-08-29 09:32:30 BST. -- Aug 29 09:31:03 volumio3a2 volumio-remote-updater[552]: [2026-08-29 09:31:03] [disconnect] Disconnect close local:[1008,Pong timeout] remote:[1006] Aug 29 09:31:08 volumio3a2 volumio-remote-updater[552]: [2026-08-29 09:31:08] [connect] Successful connection Aug 29 09:31:13 volumio3a2 volumio[941]: info: Preparing to generate the ALSA configuration file Aug 29 09:31:17 volumio3a2 volumio[941]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 29 09:31:17 volumio3a2 volumio[941]: Upnp client error: Error: This socket has been ended by the other party Aug 29 09:31:17 volumio3a2 volumio[941]: verbose: New Socket.io Connection to 192.168.1.100:3000 from 192.168.1.242 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 2 Aug 29 09:31:17 volumio3a2 volumio[941]: verbose: New Socket.io Connection to 192.168.1.100:3000 from 192.168.1.242 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 3 Aug 29 09:31:17 volumio3a2 volumio[941]: Upnp client error: Error: This socket has been ended by the other party Aug 29 09:31:17 volumio3a2 volumio[941]: Upnp client error: Error: This socket has been ended by the other party Aug 29 09:31:17 volumio3a2 volumio[941]: Upnp client error: Error: This socket has been ended by the other party Aug 29 09:31:17 volumio3a2 volumio[941]: Upnp client error: Error: This socket has been ended by the other party Aug 29 09:31:17 volumio3a2 volumio[941]: Upnp client error: Error: This socket has been ended by the other party Aug 29 09:31:17 volumio3a2 volumio[941]: Upnp client error: Error: This socket has been ended by the other party Aug 29 09:31:17 volumio3a2 volumio[941]: Upnp client error: Error: This socket has been ended by the other party Aug 29 09:31:17 volumio3a2 volumio[941]: info: Asound.conf file unchanged, so no further update is needed Aug 29 09:31:17 volumio3a2 volumio[941]: info: Output device has changed, restarting MPD Aug 29 09:31:17 volumio3a2 volumio[941]: info: Output device has changed, restarting Shairport Sync Aug 29 09:31:17 volumio3a2 volumio[941]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 09:31:17 volumio3a2 volumio[941]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 09:31:17 volumio3a2 sudo[4858]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 29 09:31:17 volumio3a2 sudo[4858]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 09:31:17 volumio3a2 sudo[4863]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 29 09:31:17 volumio3a2 sudo[4863]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 09:31:17 volumio3a2 sudo[4858]: pam_unix(sudo:session): session closed for user root Aug 29 09:31:17 volumio3a2 systemd[1]: Stopping Music Player Daemon... Aug 29 09:31:17 volumio3a2 volumio[941]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 29 09:31:17 volumio3a2 volumio[941]: info: PLUGIN START: fusiondsp Aug 29 09:31:17 volumio3a2 volumio[941]: info: Loading i18n strings for locale en Aug 29 09:31:17 volumio3a2 volumio[941]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Aug 29 09:31:17 volumio3a2 volumio[941]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 09:31:17 volumio3a2 volumio[941]: info: FusionDsp - mixtype--------------------- Hardware Aug 29 09:31:17 volumio3a2 volumio[941]: info: Preparing to generate the ALSA configuration file Aug 29 09:31:17 volumio3a2 volumio[941]: info: Done. Aug 29 09:31:17 volumio3a2 volumio[941]: info: FusionDsp - Aug 29 09:31:17 volumio3a2 volumio[941]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Aug 29 09:31:17 volumio3a2 volumio[941]: info: Reading ALSA contributions from plugins. Aug 29 09:31:17 volumio3a2 volumio[941]: info: FusionDsp - undefined Aug 29 09:31:17 volumio3a2 volumio[941]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 29 09:31:17 volumio3a2 volumio[941]: info: MPD Permissions set Aug 29 09:31:17 volumio3a2 volumio[941]: info: Selecting previously unselected package gcc. Aug 29 09:31:17 volumio3a2 volumio[941]: info: Preparing to unpack .../06-gcc_4%3a8.3.0-1+rpi2_armhf.deb ... Aug 29 09:31:17 volumio3a2 volumio[941]: info: Unpacking gcc (4:8.3.0-1+rpi2) ... Aug 29 09:31:17 volumio3a2 volumio[941]: info: Selecting previously unselected package libstdc++-8-dev:armhf. Aug 29 09:31:17 volumio3a2 volumio[941]: info: Preparing to unpack .../07-libstdc++-8-dev_8.3.0-6+rpi1_armhf.deb ... Aug 29 09:31:17 volumio3a2 volumio[941]: info: Unpacking libstdc++-8-dev:armhf (8.3.0-6+rpi1) ... Aug 29 09:31:18 volumio3a2 volumio[941]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 09:31:18 volumio3a2 volumio[941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 09:31:18 volumio3a2 volumio[941]: info: Discovery: Getting this device information Aug 29 09:31:18 volumio3a2 volumio[941]: info: CoreCommandRouter::volumioGetState Aug 29 09:31:18 volumio3a2 volumio[941]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 09:31:18 volumio3a2 volumio[941]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 09:31:18 volumio3a2 volumio[941]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 09:31:18 volumio3a2 volumio[941]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 09:31:18 volumio3a2 volumio[941]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 09:31:18 volumio3a2 volumio[941]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 09:31:18 volumio3a2 volumio[941]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 09:31:18 volumio3a2 volumio[941]: info: FusionDsp - Aug 29 09:31:20 volumio3a2 volumio-remote-updater[552]: [2026-08-29 09:31:20] [connect] Successful connection Aug 29 09:31:24 volumio3a2 go-librespot[1249]: time="2026-08-29T09:31:24+01:00" level=trace msg="received accesspoint ping" Aug 29 09:31:24 volumio3a2 go-librespot[1249]: time="2026-08-29T09:31:24+01:00" level=trace msg="received accesspoint pong ack" Aug 29 09:31:24 volumio3a2 go-librespot[1249]: time="2026-08-29T09:31:24+01:00" level=trace msg="sent dealer ping" Aug 29 09:31:24 volumio3a2 go-librespot[1249]: time="2026-08-29T09:31:24+01:00" level=trace msg="received dealer pong" Aug 29 09:31:35 volumio3a2 volumio-remote-updater[552]: [2026-08-29 09:31:35] [connect] Successful connection Aug 29 09:31:39 volumio3a2 volumio[941]: info: FusionDsp - undefined Aug 29 09:31:50 volumio3a2 volumio-remote-updater[552]: [2026-08-29 09:31:50] [connect] Successful connection Aug 29 09:31:54 volumio3a2 go-librespot[1249]: time="2026-08-29T09:31:54+01:00" level=trace msg="sent dealer ping" Aug 29 09:31:54 volumio3a2 go-librespot[1249]: time="2026-08-29T09:31:54+01:00" level=trace msg="received dealer pong" Aug 29 09:32:05 volumio3a2 volumio-remote-updater[552]: [2026-08-29 09:32:05] [connect] Successful connection Aug 29 09:32:18 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:18+01:00" level=debug msg="handling transfer player command from d97a08f441113ca5bf0bdf62fb71a9a2056f6bcd" Aug 29 09:32:20 volumio3a2 volumio-remote-updater[552]: [2026-08-29 09:32:20] [connect] Successful connection Aug 29 09:32:21 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:21+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 282" Aug 29 09:32:21 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:21+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1460" Aug 29 09:32:24 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:24+01:00" level=trace msg="sent dealer ping" Aug 29 09:32:24 volumio3a2 volumio[941]: info: camilladsp service started and running in background, instance 1 Aug 29 09:32:24 volumio3a2 volumio[941]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 09:32:24 volumio3a2 volumio[941]: /bin/sh: 1: /data/plugins/audio_interface/fusiondsp/hw_params: not found Aug 29 09:32:24 volumio3a2 volumio[941]: error: FusionDsp - ----Hw detection failed :Error: Command failed: /data/plugins/audio_interface/fusiondsp/hw_params volumioHw >/data/configuration/audio_interface/fusiondsp/hwinfo.json Aug 29 09:32:24 volumio3a2 volumio[941]: /bin/sh: 1: /data/plugins/audio_interface/fusiondsp/hw_params: not found Aug 29 09:32:24 volumio3a2 volumio[941]: info: FusionDsp loaded Aug 29 09:32:24 volumio3a2 volumio[941]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 09:32:24 volumio3a2 volumio[941]: info: FusionDsp - Reporting Fusion DSP Enabled Aug 29 09:32:24 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:24+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1E4vlGXFLxwhTT" Aug 29 09:32:24 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:24+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1E4vlGXFLxwhTT" Aug 29 09:32:24 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:24+01:00" level=debug msg="loading track (paused: true, position: 397428ms)" uri="spotify:track:1FD6J8Z27vfGgGgCbPHCks" Aug 29 09:32:25 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:24+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 09:32:25 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:24+01:00" level=trace msg="emitting websocket event: will_play" Aug 29 09:32:25 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:24+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 439" Aug 29 09:32:25 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:25+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1456" Aug 29 09:32:25 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:25+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 439" Aug 29 09:32:25 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:25+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1232" Aug 29 09:32:25 volumio3a2 volumio[941]: info: Adding Signal Path Element [object Object] Aug 29 09:32:25 volumio3a2 volumio[941]: info: Adding fusiondspeq DSP Signal Path Element Aug 29 09:32:25 volumio3a2 volumio[941]: info: FusionDsp - ---- installed callbackRead Aug 29 09:32:25 volumio3a2 volumio[941]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 09:32:25 volumio3a2 volumio[941]: Error: spawn /data/plugins/audio_interface/fusiondsp/camilladsp ENOENT Aug 29 09:32:25 volumio3a2 volumio[941]: at Process.ChildProcess._handle.onexit (internal/child_process.js:269:19) Aug 29 09:32:25 volumio3a2 volumio[941]: at onErrorNT (internal/child_process.js:465:16) Aug 29 09:32:25 volumio3a2 volumio[941]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Aug 29 09:32:25 volumio3a2 volumio[941]: at runNextTicks (internal/process/task_queues.js:62:3) Aug 29 09:32:25 volumio3a2 volumio[941]: at listOnTimeout (internal/timers.js:523:9) Aug 29 09:32:25 volumio3a2 volumio[941]: at processTimers (internal/timers.js:497:7) { Aug 29 09:32:25 volumio3a2 volumio[941]: errno: -2, Aug 29 09:32:25 volumio3a2 volumio[941]: code: 'ENOENT', Aug 29 09:32:25 volumio3a2 volumio[941]: syscall: 'spawn /data/plugins/audio_interface/fusiondsp/camilladsp', Aug 29 09:32:25 volumio3a2 volumio[941]: path: '/data/plugins/audio_interface/fusiondsp/camilladsp', Aug 29 09:32:25 volumio3a2 volumio[941]: spawnargs: [ Aug 29 09:32:25 volumio3a2 volumio[941]: '-p', Aug 29 09:32:25 volumio3a2 volumio[941]: 9876, Aug 29 09:32:25 volumio3a2 volumio[941]: '-o', Aug 29 09:32:25 volumio3a2 volumio[941]: '/tmp/camilladsp.log', Aug 29 09:32:25 volumio3a2 volumio[941]: '-l', Aug 29 09:32:25 volumio3a2 volumio[941]: 'warn', Aug 29 09:32:25 volumio3a2 volumio[941]: '/data/configuration/audio_interface/fusiondsp/camilladsp.yml' Aug 29 09:32:25 volumio3a2 volumio[941]: ] Aug 29 09:32:25 volumio3a2 volumio[941]: } Aug 29 09:32:26 volumio3a2 volumio[941]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 09:32:26 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:25+01:00" level=debug msg="selected format OGG_VORBIS_320 (86bf376d4674059833709e50dc1197ef5bdc52ec)" uri="spotify:track:1FD6J8Z27vfGgGgCbPHCks" Aug 29 09:32:26 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:25+01:00" level=debug msg="requested aes key for file 86bf376d4674059833709e50dc1197ef5bdc52ec, gid: 1FD6J8Z27vfGgGgCbPHCks" Aug 29 09:32:26 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:25+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:1FD6J8Z27vfGgGgCbPHCks" Aug 29 09:32:26 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:26+01:00" level=debug msg="fetched first chunk of 32, total size is 16638808 bytes" uri="spotify:track:1FD6J8Z27vfGgGgCbPHCks" Aug 29 09:32:26 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:26+01:00" level=debug msg="fetched chunk 2/31, size: 524288" uri="spotify:track:1FD6J8Z27vfGgGgCbPHCks" Aug 29 09:32:27 volumio3a2 sudo[5033]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Aug 29 09:32:27 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:27+01:00" level=debug msg="fetched chunk 31/31, size: 385880" uri="spotify:track:1FD6J8Z27vfGgGgCbPHCks" Aug 29 09:32:27 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:27+01:00" level=trace msg="seek to 397428ms (diff: 139ms, samples: 17526574, bytes: 16512799)" uri="spotify:track:1FD6J8Z27vfGgGgCbPHCks" Aug 29 09:32:27 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:27+01:00" level=info msg="loaded track \"Elephants On Ice Skates\" (paused: true, position: 397428ms, duration: 401320ms, prefetched: false)" uri="spotify:track:1FD6J8Z27vfGgGgCbPHCks" Aug 29 09:32:27 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:27+01:00" level=debug msg="fetched chunk 3/31, size: 524288" uri="spotify:track:1FD6J8Z27vfGgGgCbPHCks" Aug 29 09:32:27 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:27+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 09:32:27 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:27+01:00" level=trace msg="emitting websocket event: metadata" Aug 29 09:32:27 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:27+01:00" level=trace msg="emitting websocket event: active" Aug 29 09:32:27 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:27+01:00" level=debug msg="sending successful reply for dealer request" Aug 29 09:32:27 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:27+01:00" level=debug msg="fetched chunk 1/31, size: 524288" uri="spotify:track:1FD6J8Z27vfGgGgCbPHCks" Aug 29 09:32:27 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:27+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 09:32:27 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:27+01:00" level=trace msg="emitting websocket event: paused" Aug 29 09:32:27 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:27+01:00" level=debug msg="handling update_context player command from d97a08f441113ca5bf0bdf62fb71a9a2056f6bcd" Aug 29 09:32:27 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:27+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 09:32:27 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:27+01:00" level=debug msg="sending successful reply for dealer request" Aug 29 09:32:27 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:27+01:00" level=error msg="failed receiving dealer message" error="failed to get reader: received close frame: status = StatusNormalClosure and reason = \"Request disconnect\"" Aug 29 09:32:27 volumio3a2 sudo[5033]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 09:32:28 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:28+01:00" level=debug msg="dealer connection opened" Aug 29 09:32:28 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:28+01:00" level=debug msg="re-established dealer connection" Aug 29 09:32:28 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:28+01:00" level=debug msg="received connection id: OWRhNWM5NzgtZmMy...NjFGRDYzMUQ0Nw==" Aug 29 09:32:28 volumio3a2 go-librespot[1249]: time="2026-08-29T09:32:28+01:00" level=debug msg="put connect state because NEW_DEVICE" Aug 29 09:32:28 volumio3a2 sudo[5033]: pam_unix(sudo:session): session closed for user root Aug 29 09:32:30 volumio3a2 sudo[5067]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-08-29 09:31 Aug 29 09:32:30 volumio3a2 sudo[5067]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="49c352e1d55e9b76c3bd7b0e3940507619bf455a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="1d32690fc900ac8c739e7eabd35ed0f570899eb8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 19 Dec 2025 02:07:26 PM CET" VOLUMIO_VERSION="3.887" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="8f8c1d964af93dfdda0f02ac4140eec2"