-- Logs begin at Thu 2019-02-14 11:12:04 CET, end at Sun 2025-11-02 13:49:18 CET. -- Nov 02 13:48:00 volumio volumio[825]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Nov 02 13:48:00 volumio volumio[825]: info: Reading ALSA contributions from plugins. Nov 02 13:48:00 volumio volumio[825]: info: Enabling plugin fusiondsp Nov 02 13:48:00 volumio volumio[825]: info: Enabling plugin fusiondsp Nov 02 13:48:00 volumio volumio[825]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 02 13:48:00 volumio volumio[825]: info: Loading plugin "fusiondsp"... Nov 02 13:48:00 volumio volumio[825]: info: Applying required configuration parameters for plugin fusiondsp Nov 02 13:48:00 volumio volumio-remote-updater[361]: [2025-11-02 13:48:00] [connect] Successful connection Nov 02 13:48:00 volumio volumio[825]: info: Loading plugin "fusiondsp"... Nov 02 13:48:00 volumio volumio[825]: info: Applying required configuration parameters for plugin fusiondsp Nov 02 13:48:01 volumio volumio[825]: info: Selecting previously unselected package dh-python. Nov 02 13:48:01 volumio volumio[825]: info: Preparing to unpack .../19-dh-python_3.20190308_all.deb ... Nov 02 13:48:01 volumio volumio[825]: info: Unpacking dh-python (3.20190308) ... Nov 02 13:48:01 volumio volumio[825]: verbose: New Socket.io Connection to 192.168.1.115 from 192.168.1.144 UA: Mozilla/5.0 (Android 15; Mobile; rv:144.0) Gecko/144.0 Firefox/144.0 Engine version: 3 Transport: polling Total Clients: 1 Nov 02 13:48:01 volumio volumio[825]: verbose: New Socket.io Connection to 192.168.1.115 from 192.168.1.144 UA: Mozilla/5.0 (Android 15; Mobile; rv:144.0) Gecko/144.0 Firefox/144.0 Engine version: 3 Transport: polling Total Clients: 2 Nov 02 13:48:01 volumio volumio-remote-updater[361]: [2025-11-02 13:48:01] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1762087680 101 Nov 02 13:48:01 volumio volumio[825]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 3 Nov 02 13:48:01 volumio volumio[825]: info: Selecting previously unselected package libfakeroot:armhf. Nov 02 13:48:01 volumio volumio[825]: info: Preparing to unpack .../20-libfakeroot_1.23-1_armhf.deb ... Nov 02 13:48:01 volumio volumio[825]: info: Unpacking libfakeroot:armhf (1.23-1) ... Nov 02 13:48:01 volumio volumio[825]: info: Selecting previously unselected package fakeroot. Nov 02 13:48:01 volumio volumio[825]: info: Preparing to unpack .../21-fakeroot_1.23-1_armhf.deb ... Nov 02 13:48:01 volumio volumio[825]: info: Unpacking fakeroot (1.23-1) ... Nov 02 13:48:01 volumio volumio[825]: info: Selecting previously unselected package libalgorithm-diff-perl. Nov 02 13:48:01 volumio volumio[825]: info: Preparing to unpack .../22-libalgorithm-diff-perl_1.19.03-2_all.deb ... Nov 02 13:48:01 volumio volumio[825]: info: Unpacking libalgorithm-diff-perl (1.19.03-2) ... Nov 02 13:48:01 volumio volumio[825]: info: FusionDsp - Nov 02 13:48:06 volumio go-librespot[1085]: time="2025-11-02T13:48:06+01:00" level=debug msg="fetched chunk 23/24, size: 524288" uri="spotify:track:3cA3PdykttZ4xqO6bJqJ27" Nov 02 13:48:09 volumio volumio[825]: info: Selecting previously unselected package libalgorithm-diff-xs-perl. Nov 02 13:48:09 volumio volumio[825]: info: Preparing to unpack .../23-libalgorithm-diff-xs-perl_0.04-5+b1_armhf.deb ... Nov 02 13:48:09 volumio volumio[825]: info: Unpacking libalgorithm-diff-xs-perl (0.04-5+b1) ... Nov 02 13:48:09 volumio volumio[825]: info: FusionDsp - undefined Nov 02 13:48:09 volumio volumio[825]: info: Selecting previously unselected package libalgorithm-merge-perl. Nov 02 13:48:09 volumio volumio[825]: info: Preparing to unpack .../24-libalgorithm-merge-perl_0.08-3_all.deb ... Nov 02 13:48:09 volumio volumio[825]: info: Unpacking libalgorithm-merge-perl (0.08-3) ... Nov 02 13:48:09 volumio volumio[825]: info: Selecting previously unselected package libexpat1-dev:armhf. Nov 02 13:48:09 volumio volumio[825]: info: Preparing to unpack .../25-libexpat1-dev_2.2.6-2+deb10u7_armhf.deb ... Nov 02 13:48:09 volumio volumio[825]: info: Unpacking libexpat1-dev:armhf (2.2.6-2+deb10u7) ... Nov 02 13:48:09 volumio volumio[825]: verbose: New Socket.io Connection to 192.168.1.115 from 192.168.1.144 UA: Mozilla/5.0 (Android 15; Mobile; rv:144.0) Gecko/144.0 Firefox/144.0 Engine version: 3 Transport: polling Total Clients: 4 Nov 02 13:48:09 volumio volumio[825]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Nov 02 13:48:09 volumio volumio[825]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Nov 02 13:48:09 volumio volumio[825]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Nov 02 13:48:10 volumio volumio[825]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Nov 02 13:48:10 volumio volumio[825]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Nov 02 13:48:10 volumio volumio[825]: info: Asound.conf file unchanged, so no further update is needed Nov 02 13:48:10 volumio volumio[825]: info: Output device has changed, restarting MPD Nov 02 13:48:10 volumio volumio[825]: info: Output device has changed, restarting Shairport Sync Nov 02 13:48:10 volumio volumio[825]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 13:48:10 volumio volumio[825]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 02 13:48:11 volumio sudo[4312]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 02 13:48:11 volumio sudo[4314]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 02 13:48:11 volumio sudo[4312]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 13:48:11 volumio sudo[4314]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 13:48:11 volumio sudo[4312]: pam_unix(sudo:session): session closed for user root Nov 02 13:48:12 volumio systemd[1]: Stopping Music Player Daemon... Nov 02 13:48:12 volumio volumio[825]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 02 13:48:12 volumio volumio[825]: info: Preparing to generate the ALSA configuration file Nov 02 13:48:12 volumio volumio[825]: info: PLUGIN START: fusiondsp Nov 02 13:48:13 volumio volumio[825]: info: Loading i18n strings for locale fr Nov 02 13:48:13 volumio go-librespot[1085]: time="2025-11-02T13:48:13+01:00" level=trace msg="received accesspoint ping" Nov 02 13:48:13 volumio go-librespot[1085]: time="2025-11-02T13:48:13+01:00" level=trace msg="received accesspoint pong ack" Nov 02 13:48:13 volumio volumio[825]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Nov 02 13:48:13 volumio volumio[825]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 13:48:13 volumio volumio[825]: info: FusionDsp - mixtype--------------------- undefined Nov 02 13:48:13 volumio volumio[825]: info: Done. Nov 02 13:48:13 volumio go-librespot[1085]: time="2025-11-02T13:48:13+01:00" level=trace msg="sent dealer ping" Nov 02 13:48:13 volumio go-librespot[1085]: time="2025-11-02T13:48:13+01:00" level=trace msg="received dealer pong" Nov 02 13:48:14 volumio volumio[825]: info: Selecting previously unselected package libpython3.7:armhf. Nov 02 13:48:14 volumio volumio[825]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Nov 02 13:48:14 volumio volumio[825]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Nov 02 13:48:14 volumio volumio[825]: info: Reading ALSA contributions from plugins. Nov 02 13:48:14 volumio volumio[825]: verbose: New Socket.io Connection to 192.168.1.115 from 192.168.1.144 UA: Mozilla/5.0 (Android 15; Mobile; rv:144.0) Gecko/144.0 Firefox/144.0 Engine version: 3 Transport: polling Total Clients: 10 Nov 02 13:48:14 volumio volumio[825]: info: MPD Permissions set Nov 02 13:48:17 volumio volumio[825]: verbose: New Socket.io Connection to 192.168.1.115 from 192.168.1.144 UA: Mozilla/5.0 (Android 15; Mobile; rv:144.0) Gecko/144.0 Firefox/144.0 Engine version: 3 Transport: polling Total Clients: 11 Nov 02 13:48:18 volumio go-librespot[1085]: time="2025-11-02T13:48:18+01:00" level=debug msg="fetched chunk 24/24, size: 147396" uri="spotify:track:3cA3PdykttZ4xqO6bJqJ27" Nov 02 13:48:20 volumio volumio[825]: info: camilladsp service started and running in background, instance 1 Nov 02 13:48:20 volumio volumio[825]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 13:48:21 volumio volumio[825]: /bin/sh: 1: /data/plugins/audio_interface/fusiondsp/hw_params: not found Nov 02 13:48:21 volumio volumio[825]: error: FusionDsp - ----Hw detection failed :Error: Command failed: /data/plugins/audio_interface/fusiondsp/hw_params volumioHw >/data/configuration/audio_interface/fusiondsp/hwinfo.json Nov 02 13:48:21 volumio volumio[825]: /bin/sh: 1: /data/plugins/audio_interface/fusiondsp/hw_params: not found Nov 02 13:48:21 volumio volumio[825]: info: FusionDsp loaded Nov 02 13:48:21 volumio volumio[825]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 02 13:48:21 volumio sudo[4353]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Nov 02 13:48:21 volumio sudo[4353]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 13:48:22 volumio volumio[825]: info: FusionDsp - Reporting Fusion DSP Enabled Nov 02 13:48:22 volumio volumio[825]: info: Adding Signal Path Element [object Object] Nov 02 13:48:22 volumio volumio[825]: info: Adding fusiondspeq DSP Signal Path Element Nov 02 13:48:22 volumio volumio[825]: info: FusionDsp - ---- installed callbackRead Nov 02 13:48:22 volumio sudo[4353]: pam_unix(sudo:session): session closed for user root Nov 02 13:48:22 volumio volumio[825]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 02 13:48:22 volumio volumio[825]: Error: spawn /data/plugins/audio_interface/fusiondsp/camilladsp ENOENT Nov 02 13:48:22 volumio volumio[825]: at Process.ChildProcess._handle.onexit (internal/child_process.js:269:19) Nov 02 13:48:22 volumio volumio[825]: at onErrorNT (internal/child_process.js:465:16) Nov 02 13:48:22 volumio volumio[825]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Nov 02 13:48:22 volumio volumio[825]: at runNextTicks (internal/process/task_queues.js:62:3) Nov 02 13:48:22 volumio volumio[825]: at listOnTimeout (internal/timers.js:523:9) Nov 02 13:48:22 volumio volumio[825]: at processTimers (internal/timers.js:497:7) { Nov 02 13:48:22 volumio volumio[825]: errno: -2, Nov 02 13:48:22 volumio volumio[825]: code: 'ENOENT', Nov 02 13:48:22 volumio volumio[825]: syscall: 'spawn /data/plugins/audio_interface/fusiondsp/camilladsp', Nov 02 13:48:22 volumio volumio[825]: path: '/data/plugins/audio_interface/fusiondsp/camilladsp', Nov 02 13:48:22 volumio volumio[825]: spawnargs: [ Nov 02 13:48:22 volumio volumio[825]: '-p', Nov 02 13:48:22 volumio volumio[825]: 9876, Nov 02 13:48:22 volumio volumio[825]: '-o', Nov 02 13:48:22 volumio volumio[825]: '/tmp/camilladsp.log', Nov 02 13:48:22 volumio volumio[825]: '-l', Nov 02 13:48:22 volumio volumio[825]: 'warn', Nov 02 13:48:22 volumio volumio[825]: '/data/configuration/audio_interface/fusiondsp/camilladsp.yml' Nov 02 13:48:22 volumio volumio[825]: ] Nov 02 13:48:22 volumio volumio[825]: } Nov 02 13:48:22 volumio volumio[825]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 02 13:48:24 volumio mpd_monitor.sh[380]: MPD Monitor Service: MPD Appears to be inactive, restarting Nov 02 13:48:30 volumio systemd[1]: mpd.service: Succeeded. Nov 02 13:48:30 volumio systemd[1]: Stopped Music Player Daemon. Nov 02 13:48:31 volumio systemd[1]: Starting Music Player Daemon... Nov 02 13:48:31 volumio volumio-remote-updater[361]: [2025-11-02 13:48:31] [disconnect] Disconnect close local:[1008,Pong timeout] remote:[1006] Nov 02 13:48:36 volumio volumio-remote-updater[361]: [2025-11-02 13:48:36] [connect] Successful connection Nov 02 13:48:41 volumio go-librespot[1085]: time="2025-11-02T13:48:41+01:00" level=debug msg="handling play player command from c0ea620e7a8a5f64b3c35560406ae95ff2ed5144" Nov 02 13:48:41 volumio go-librespot[1085]: time="2025-11-02T13:48:41+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DZ06evO1fn6V6" Nov 02 13:48:41 volumio go-librespot[1085]: time="2025-11-02T13:48:41+01:00" level=trace msg="fetched new page 0 with 23 items (list: 23)" uri="spotify:playlist:37i9dQZF1DZ06evO1fn6V6" Nov 02 13:48:41 volumio go-librespot[1085]: time="2025-11-02T13:48:41+01:00" level=debug msg="shuffled context with seed 17406857688530265350 (len: 23, keep: 12)" uri="spotify:playlist:37i9dQZF1DZ06evO1fn6V6" Nov 02 13:48:41 volumio sudo[4376]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 02 13:48:41 volumio sudo[4376]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 13:48:42 volumio sudo[4376]: pam_unix(sudo:session): session closed for user root Nov 02 13:48:42 volumio go-librespot[1085]: time="2025-11-02T13:48:42+01:00" level=debug msg="loading track (paused: false, position: 420ms)" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:48:42 volumio go-librespot[1085]: time="2025-11-02T13:48:42+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 02 13:48:42 volumio go-librespot[1085]: time="2025-11-02T13:48:42+01:00" level=trace msg="emitting websocket event: will_play" Nov 02 13:48:48 volumio volumio-remote-updater[361]: [2025-11-02 13:48:48] [connect] Successful connection Nov 02 13:48:52 volumio go-librespot[1085]: time="2025-11-02T13:48:52+01:00" level=debug msg="selected format OGG_VORBIS_320 (2ae54a8874ea6e94902393cc3e9b4ea9761dc78c)" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:48:55 volumio go-librespot[1085]: time="2025-11-02T13:48:52+01:00" level=debug msg="requested aes key for file 2ae54a8874ea6e94902393cc3e9b4ea9761dc78c, gid: 47PkdwJRX4sTQqH4S819yw" Nov 02 13:48:55 volumio go-librespot[1085]: time="2025-11-02T13:48:52+01:00" level=trace msg="sent dealer ping" Nov 02 13:48:55 volumio go-librespot[1085]: time="2025-11-02T13:48:52+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:48:55 volumio go-librespot[1085]: time="2025-11-02T13:48:53+01:00" level=debug msg="fetched first chunk of 22, total size is 11436512 bytes" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:48:55 volumio go-librespot[1085]: time="2025-11-02T13:48:53+01:00" level=trace msg="seek to 420ms (diff: 48ms, samples: 18522, bytes: 14360)" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:48:55 volumio go-librespot[1085]: time="2025-11-02T13:48:53+01:00" level=info msg="loaded track \"Shock The Water\" (paused: false, position: 420ms, duration: 268000ms, prefetched: false)" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:48:55 volumio go-librespot[1085]: time="2025-11-02T13:48:53+01:00" level=debug msg="fetched chunk 2/21, size: 524288" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:48:55 volumio go-librespot[1085]: time="2025-11-02T13:48:53+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 02 13:48:55 volumio go-librespot[1085]: time="2025-11-02T13:48:53+01:00" level=trace msg="scheduling prefetch in 238s" Nov 02 13:48:55 volumio go-librespot[1085]: time="2025-11-02T13:48:53+01:00" level=trace msg="emitting websocket event: metadata" Nov 02 13:48:55 volumio go-librespot[1085]: time="2025-11-02T13:48:55+01:00" level=debug msg="sending successful reply for dealer request" Nov 02 13:48:55 volumio go-librespot[1085]: time="2025-11-02T13:48:55+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 02 13:48:55 volumio go-librespot[1085]: time="2025-11-02T13:48:55+01:00" level=trace msg="emitting websocket event: playing" Nov 02 13:48:55 volumio go-librespot[1085]: time="2025-11-02T13:48:55+01:00" level=debug msg="handling transfer player command from c0ea620e7a8a5f64b3c35560406ae95ff2ed5144" Nov 02 13:48:59 volumio go-librespot[1085]: time="2025-11-02T13:48:59+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DZ06evO1fn6V6" Nov 02 13:48:59 volumio go-librespot[1085]: time="2025-11-02T13:48:59+01:00" level=trace msg="fetched new page 0 with 23 items (list: 23)" uri="spotify:playlist:37i9dQZF1DZ06evO1fn6V6" Nov 02 13:48:59 volumio go-librespot[1085]: time="2025-11-02T13:48:59+01:00" level=debug msg="shuffled context with seed 2902510330052396682 (len: 23, keep: 7)" uri="spotify:playlist:37i9dQZF1DZ06evO1fn6V6" Nov 02 13:48:59 volumio go-librespot[1085]: time="2025-11-02T13:48:59+01:00" level=debug msg="fetched chunk 1/21, size: 524288" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:00 volumio go-librespot[1085]: time="2025-11-02T13:49:00+01:00" level=debug msg="loading track (paused: false, position: 18701ms)" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:00 volumio go-librespot[1085]: time="2025-11-02T13:49:00+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 431" Nov 02 13:49:00 volumio go-librespot[1085]: time="2025-11-02T13:49:00+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1173" Nov 02 13:49:00 volumio go-librespot[1085]: time="2025-11-02T13:49:00+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 378" Nov 02 13:49:00 volumio go-librespot[1085]: time="2025-11-02T13:49:00+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1403" Nov 02 13:49:00 volumio go-librespot[1085]: time="2025-11-02T13:49:00+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 02 13:49:01 volumio go-librespot[1085]: time="2025-11-02T13:49:00+01:00" level=trace msg="emitting websocket event: will_play" Nov 02 13:49:01 volumio go-librespot[1085]: time="2025-11-02T13:49:01+01:00" level=debug msg="selected format OGG_VORBIS_320 (2ae54a8874ea6e94902393cc3e9b4ea9761dc78c)" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:02 volumio go-librespot[1085]: time="2025-11-02T13:49:01+01:00" level=debug msg="requested aes key for file 2ae54a8874ea6e94902393cc3e9b4ea9761dc78c, gid: 47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:02 volumio go-librespot[1085]: time="2025-11-02T13:49:02+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:02 volumio go-librespot[1085]: time="2025-11-02T13:49:02+01:00" level=debug msg="fetched chunk 3/21, size: 524288" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:03 volumio volumio-remote-updater[361]: [2025-11-02 13:49:03] [connect] Successful connection Nov 02 13:49:04 volumio go-librespot[1085]: time="2025-11-02T13:49:04+01:00" level=debug msg="fetched first chunk of 22, total size is 11436512 bytes" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:04 volumio go-librespot[1085]: time="2025-11-02T13:49:04+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 431" Nov 02 13:49:04 volumio go-librespot[1085]: time="2025-11-02T13:49:04+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1399" Nov 02 13:49:04 volumio go-librespot[1085]: time="2025-11-02T13:49:04+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1173" Nov 02 13:49:07 volumio go-librespot[1085]: time="2025-11-02T13:49:07+01:00" level=debug msg="fetched chunk 2/21, size: 524288" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:08 volumio go-librespot[1085]: time="2025-11-02T13:49:08+01:00" level=debug msg="fetched chunk 1/21, size: 524288" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:08 volumio go-librespot[1085]: time="2025-11-02T13:49:08+01:00" level=trace msg="seek to 18701ms (diff: 52ms, samples: 824714, bytes: 761122)" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:09 volumio go-librespot[1085]: time="2025-11-02T13:49:09+01:00" level=debug msg="fetched chunk 3/21, size: 524288" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:09 volumio go-librespot[1085]: time="2025-11-02T13:49:09+01:00" level=debug msg="fetched chunk 4/21, size: 524288" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:09 volumio go-librespot[1085]: time="2025-11-02T13:49:09+01:00" level=info msg="loaded track \"Shock The Water\" (paused: false, position: 18701ms, duration: 268000ms, prefetched: false)" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:09 volumio go-librespot[1085]: time="2025-11-02T13:49:09+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 02 13:49:09 volumio go-librespot[1085]: time="2025-11-02T13:49:09+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1118" Nov 02 13:49:09 volumio go-librespot[1085]: time="2025-11-02T13:49:09+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 391" Nov 02 13:49:10 volumio go-librespot[1085]: time="2025-11-02T13:49:10+01:00" level=trace msg="scheduling prefetch in 219s" Nov 02 13:49:10 volumio go-librespot[1085]: time="2025-11-02T13:49:10+01:00" level=trace msg="emitting websocket event: metadata" Nov 02 13:49:10 volumio go-librespot[1085]: time="2025-11-02T13:49:10+01:00" level=trace msg="emitting websocket event: active" Nov 02 13:49:10 volumio go-librespot[1085]: time="2025-11-02T13:49:10+01:00" level=debug msg="sending successful reply for dealer request" Nov 02 13:49:10 volumio go-librespot[1085]: time="2025-11-02T13:49:10+01:00" level=trace msg="received dealer pong" Nov 02 13:49:10 volumio go-librespot[1085]: time="2025-11-02T13:49:10+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 02 13:49:10 volumio go-librespot[1085]: time="2025-11-02T13:49:10+01:00" level=trace msg="emitting websocket event: playing" Nov 02 13:49:10 volumio go-librespot[1085]: time="2025-11-02T13:49:10+01:00" level=debug msg="handling transfer player command from c0ea620e7a8a5f64b3c35560406ae95ff2ed5144" Nov 02 13:49:10 volumio go-librespot[1085]: time="2025-11-02T13:49:10+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DZ06evO1fn6V6" Nov 02 13:49:10 volumio go-librespot[1085]: time="2025-11-02T13:49:10+01:00" level=trace msg="fetched new page 0 with 23 items (list: 23)" uri="spotify:playlist:37i9dQZF1DZ06evO1fn6V6" Nov 02 13:49:10 volumio go-librespot[1085]: time="2025-11-02T13:49:10+01:00" level=debug msg="shuffled context with seed 17467932958117137304 (len: 23, keep: 6)" uri="spotify:playlist:37i9dQZF1DZ06evO1fn6V6" Nov 02 13:49:10 volumio go-librespot[1085]: time="2025-11-02T13:49:10+01:00" level=debug msg="loading track (paused: false, position: 17456ms)" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:10 volumio go-librespot[1085]: time="2025-11-02T13:49:10+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 02 13:49:10 volumio go-librespot[1085]: time="2025-11-02T13:49:10+01:00" level=trace msg="emitting websocket event: will_play" Nov 02 13:49:11 volumio go-librespot[1085]: time="2025-11-02T13:49:11+01:00" level=debug msg="selected format OGG_VORBIS_320 (2ae54a8874ea6e94902393cc3e9b4ea9761dc78c)" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:11 volumio go-librespot[1085]: time="2025-11-02T13:49:11+01:00" level=debug msg="requested aes key for file 2ae54a8874ea6e94902393cc3e9b4ea9761dc78c, gid: 47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:11 volumio go-librespot[1085]: time="2025-11-02T13:49:11+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:12 volumio go-librespot[1085]: time="2025-11-02T13:49:12+01:00" level=debug msg="fetched first chunk of 22, total size is 11436512 bytes" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:13 volumio go-librespot[1085]: time="2025-11-02T13:49:13+01:00" level=trace msg="sent dealer ping" Nov 02 13:49:14 volumio go-librespot[1085]: time="2025-11-02T13:49:14+01:00" level=debug msg="fetched chunk 1/21, size: 524288" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:14 volumio go-librespot[1085]: time="2025-11-02T13:49:14+01:00" level=trace msg="seek to 17456ms (diff: 116ms, samples: 769809, bytes: 710149)" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:14 volumio go-librespot[1085]: time="2025-11-02T13:49:14+01:00" level=debug msg="fetched chunk 2/21, size: 524288" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:15 volumio go-librespot[1085]: time="2025-11-02T13:49:15+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 431" Nov 02 13:49:15 volumio go-librespot[1085]: time="2025-11-02T13:49:15+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1173" Nov 02 13:49:15 volumio go-librespot[1085]: time="2025-11-02T13:49:15+01:00" level=info msg="loaded track \"Shock The Water\" (paused: false, position: 17456ms, duration: 268000ms, prefetched: false)" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:15 volumio go-librespot[1085]: time="2025-11-02T13:49:15+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 02 13:49:15 volumio go-librespot[1085]: time="2025-11-02T13:49:15+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1118" Nov 02 13:49:15 volumio go-librespot[1085]: time="2025-11-02T13:49:15+01:00" level=debug msg="fetched chunk 4/21, size: 524288" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:15 volumio go-librespot[1085]: time="2025-11-02T13:49:15+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 391" Nov 02 13:49:16 volumio go-librespot[1085]: time="2025-11-02T13:49:16+01:00" level=trace msg="scheduling prefetch in 221s" Nov 02 13:49:16 volumio go-librespot[1085]: time="2025-11-02T13:49:16+01:00" level=trace msg="emitting websocket event: metadata" Nov 02 13:49:16 volumio go-librespot[1085]: time="2025-11-02T13:49:16+01:00" level=trace msg="emitting websocket event: active" Nov 02 13:49:16 volumio go-librespot[1085]: time="2025-11-02T13:49:16+01:00" level=debug msg="sending successful reply for dealer request" Nov 02 13:49:16 volumio go-librespot[1085]: time="2025-11-02T13:49:16+01:00" level=debug msg="fetched chunk 3/21, size: 524288" uri="spotify:track:47PkdwJRX4sTQqH4S819yw" Nov 02 13:49:16 volumio go-librespot[1085]: time="2025-11-02T13:49:16+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 02 13:49:16 volumio go-librespot[1085]: time="2025-11-02T13:49:16+01:00" level=trace msg="emitting websocket event: playing" Nov 02 13:49:16 volumio go-librespot[1085]: time="2025-11-02T13:49:16+01:00" level=info msg="playback was transferred to SM-G970F" Nov 02 13:49:17 volumio go-librespot[1085]: time="2025-11-02T13:49:17+01:00" level=trace msg="closed output device because of stop command" Nov 02 13:49:17 volumio go-librespot[1085]: time="2025-11-02T13:49:17+01:00" level=debug msg="put connect state inactive" Nov 02 13:49:17 volumio go-librespot[1085]: time="2025-11-02T13:49:17+01:00" level=trace msg="emitting websocket event: inactive" Nov 02 13:49:17 volumio go-librespot[1085]: time="2025-11-02T13:49:17+01:00" level=trace msg="emitting websocket event: stopped" Nov 02 13:49:17 volumio go-librespot[1085]: time="2025-11-02T13:49:17+01:00" level=debug msg="dealer connection closed" Nov 02 13:49:17 volumio go-librespot[1085]: time="2025-11-02T13:49:17+01:00" level=debug msg="dealer recv loop stopped" Nov 02 13:49:17 volumio go-librespot[1085]: time="2025-11-02T13:49:17+01:00" level=warning msg="unknown dealer request: " Nov 02 13:49:17 volumio go-librespot[1085]: time="2025-11-02T13:49:17+01:00" level=debug msg="sending successful reply for dealer request" Nov 02 13:49:17 volumio go-librespot[1085]: time="2025-11-02T13:49:17+01:00" level=debug msg="obtained new client token: AADxxeULpnUwZ6Mo3m0L53zPXjiZQONtN50lAhFS3D733AZzoLV5hRVEEjhRfzKeJtQgdfxyZwGF//x7lv79x5PsxwjX2ODmKEtvPEl3pyKcvY+Ez10DO4JHLPOo/rq31qcxg6kxmPNK0YDbVAkesoUxZXpr/mQtaXDby6LvrZEuwJtlq6RBVu7ovYSj/c0wOD2NPuHSXhXsGszffKSw6ymYk6aDNQPLj7t9ThomJpQ5JUOg5sOBSMKu2qU+" Nov 02 13:49:17 volumio go-librespot[1085]: time="2025-11-02T13:49:17+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 02 13:49:18 volumio go-librespot[1085]: time="2025-11-02T13:49:18+01:00" level=debug msg="completed keyexchange" Nov 02 13:49:18 volumio go-librespot[1085]: time="2025-11-02T13:49:18+01:00" level=debug msg="completed challenge" Nov 02 13:49:18 volumio go-librespot[1085]: time="2025-11-02T13:49:18+01:00" level=info msg="authenticated AP" username="el******ar" Nov 02 13:49:18 volumio go-librespot[1085]: time="2025-11-02T13:49:18+01:00" level=info msg="authenticated Login5" username="el******ar" Nov 02 13:49:18 volumio go-librespot[1085]: time="2025-11-02T13:49:18+01:00" level=debug msg="restored session after logout" username="el******ar" Nov 02 13:49:18 volumio sudo[4496]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-11-02 13:48 Nov 02 13:49:18 volumio sudo[4496]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 13:49:18 volumio go-librespot[1085]: time="2025-11-02T13:49:18+01:00" level=debug msg="dealer connection opened" Nov 02 13:49:18 volumio go-librespot[1085]: time="2025-11-02T13:49:18+01:00" level=trace msg="starting accesspoint recv loop" Nov 02 13:49:18 volumio go-librespot[1085]: time="2025-11-02T13:49:18+01:00" level=trace msg="starting dealer recv loop" Nov 02 13:49:18 volumio go-librespot[1085]: time="2025-11-02T13:49:18+01:00" level=trace msg="received accesspoint ping" Nov 02 13:49:18 volumio go-librespot[1085]: time="2025-11-02T13:49:18+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Nov 02 13:49:18 volumio go-librespot[1085]: time="2025-11-02T13:49:18+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Nov 02 13:49:18 volumio go-librespot[1085]: time="2025-11-02T13:49:18+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Nov 02 13:49:18 volumio go-librespot[1085]: time="2025-11-02T13:49:18+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Nov 02 13:49:18 volumio go-librespot[1085]: time="2025-11-02T13:49:18+01:00" level=debug msg="received connection id: NmUyMDBiZWUtMDE2...Qjg2OEJFMENBNA==" Nov 02 13:49:18 volumio volumio-remote-updater[361]: [2025-11-02 13:49:18] [connect] Successful connection Nov 02 13:49:18 volumio go-librespot[1085]: time="2025-11-02T13:49:18+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Nov 02 13:49:18 volumio go-librespot[1085]: time="2025-11-02T13:49:18+01:00" level=trace msg="received accesspoint pong ack" Nov 02 13:49:18 volumio go-librespot[1085]: time="2025-11-02T13:49:18+01:00" level=debug msg="put connect state because NEW_DEVICE" 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="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"