Dec 19 16:08:05 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:05+01:00" level=trace msg="sent dealer ping" Dec 19 16:08:05 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:05+01:00" level=trace msg="received dealer pong" Dec 19 16:08:05 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 19 16:08:05 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 19 16:08:16 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:16+01:00" level=debug msg="prefetching next track" uri="spotify:track:4p0XPFssN6vgbyDj7V9IP6" Dec 19 16:08:16 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:16+01:00" level=debug msg="selected format OGG_VORBIS_320 (d458fcef9c442dddec47428eb49a5670a04ef0a2)" uri="spotify:track:4p0XPFssN6vgbyDj7V9IP6" Dec 19 16:08:16 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:16+01:00" level=debug msg="requested aes key for file d458fcef9c442dddec47428eb49a5670a04ef0a2, gid: 4p0XPFssN6vgbyDj7V9IP6" Dec 19 16:08:16 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:16+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4p0XPFssN6vgbyDj7V9IP6" Dec 19 16:08:16 volumio-4 volumio[2612]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/peppyspectrum/volumio/bookworm/armhf Dec 19 16:08:17 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:17+01:00" level=debug msg="fetched first chunk of 14, total size is 7337828 bytes" uri="spotify:track:4p0XPFssN6vgbyDj7V9IP6" Dec 19 16:08:17 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:17+01:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Dec 19 16:08:17 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:17+01:00" level=info msg="prefetched track \"Saudade da Bahia\" (duration: 196760ms)" uri="spotify:track:4p0XPFssN6vgbyDj7V9IP6" Dec 19 16:08:17 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:17+01:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:4p0XPFssN6vgbyDj7V9IP6" Dec 19 16:08:17 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:17+01:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:4p0XPFssN6vgbyDj7V9IP6" Dec 19 16:08:17 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:17+01:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:4p0XPFssN6vgbyDj7V9IP6" Dec 19 16:08:18 volumio-4 volumio[2612]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/peppyspectrum/volumio/bookworm/armhf Dec 19 16:08:18 volumio-4 volumio[2612]: info: Folder /tmp/plugins removed Dec 19 16:08:18 volumio-4 volumio[2612]: info: Check plugin dependencies Dec 19 16:08:18 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 19 16:08:18 volumio-4 volumio[2612]: info: Checking if plugin already exists Dec 19 16:08:18 volumio-4 volumio[2612]: info: Rename folder Dec 19 16:08:18 volumio-4 volumio[2612]: info: Folder /tmp/downloaded_plugin.zip removed Dec 19 16:08:18 volumio-4 volumio[2612]: info: Move to category Dec 19 16:08:18 volumio-4 volumio[2612]: info: Checking if install.sh is present Dec 19 16:08:18 volumio-4 volumio[2612]: info: Executing install.sh Dec 19 16:08:18 volumio-4 sudo[5020]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/user_interface/peppyspectrum/install.sh Dec 19 16:08:18 volumio-4 sudo[5020]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:18 volumio-4 volumio[2612]: info: Installing peppyalsa plugin dependencies Dec 19 16:08:18 volumio-4 sudo[5024]: root : PWD=/ ; USER=root ; COMMAND=/usr/sbin/usermod -aG render volumio Dec 19 16:08:18 volumio-4 sudo[5024]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 19 16:08:18 volumio-4 sudo[5024]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:18 volumio-4 sudo[5029]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/apt-get update Dec 19 16:08:18 volumio-4 sudo[5029]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 19 16:08:18 volumio-4 volumio[2612]: info: Hit:1 http://raspbian.raspberrypi.com/raspbian bookworm InRelease Dec 19 16:08:18 volumio-4 volumio[2612]: info: Hit:2 https://deb.nodesource.com/node_20.x nodistro InRelease Dec 19 16:08:19 volumio-4 volumio[2612]: info: Hit:3 http://archive.raspberrypi.com/debian bookworm InRelease Dec 19 16:08:21 volumio-4 volumio[2612]: info: Reading package lists... Dec 19 16:08:21 volumio-4 sudo[5029]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:21 volumio-4 sudo[5206]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/chown -R volumio /data/plugins/user_interface/peppyspectrum /data/INTERNAL/PeppySpectrum/Templates Dec 19 16:08:21 volumio-4 sudo[5206]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 19 16:08:21 volumio-4 sudo[5206]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:21 volumio-4 sudo[5208]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/chgrp -R volumio /data/plugins/user_interface/peppyspectrum /data/INTERNAL/PeppySpectrum/Templates Dec 19 16:08:21 volumio-4 sudo[5208]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 19 16:08:21 volumio-4 sudo[5208]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:21 volumio-4 volumio[2612]: info: installing apt packages Dec 19 16:08:21 volumio-4 sudo[5210]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/apt-get -y install python3-pygame python3-pillow libfftw3-dev Dec 19 16:08:21 volumio-4 sudo[5210]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 19 16:08:21 volumio-4 volumio[2612]: info: Reading package lists... Dec 19 16:08:21 volumio-4 volumio[2612]: info: Building dependency tree... Dec 19 16:08:21 volumio-4 volumio[2612]: info: Reading state information... Dec 19 16:08:22 volumio-4 volumio[2612]: info: python3-pygame is already the newest version (2.1.2+dfsg-5). Dec 19 16:08:22 volumio-4 volumio[2612]: info: libfftw3-dev is already the newest version (3.3.10-1). Dec 19 16:08:22 volumio-4 volumio[2612]: info: The following additional packages will be installed: Dec 19 16:08:22 volumio-4 volumio[2612]: info: bzip2 file libimagequant0 libraqm0 mailcap mime-support python3-olefile Dec 19 16:08:22 volumio-4 volumio[2612]: info: Suggested packages: Dec 19 16:08:22 volumio-4 volumio[2612]: info: bzip2-doc python-pil-doc Dec 19 16:08:22 volumio-4 volumio[2612]: info: The following NEW packages will be installed: Dec 19 16:08:22 volumio-4 volumio[2612]: info: bzip2 file libimagequant0 libraqm0 mailcap mime-support python3-olefile Dec 19 16:08:22 volumio-4 volumio[2612]: info: python3-pil Dec 19 16:08:22 volumio-4 volumio[2612]: info: 0 upgraded, 8 newly installed, 0 to remove and 13 not upgraded. Dec 19 16:08:22 volumio-4 volumio[2612]: info: Need to get 638 kB of archives. Dec 19 16:08:22 volumio-4 volumio[2612]: info: After this operation, 2248 kB of additional disk space will be used. Dec 19 16:08:22 volumio-4 volumio[2612]: info: Get:1 http://raspbian.raspberrypi.com/raspbian bookworm/main armhf bzip2 armhf 1.0.8-5+b2 [47.4 kB] Dec 19 16:08:22 volumio-4 volumio[2612]: info: Get:2 http://ftp.arnes.si/mirrors/raspbian/raspbian bookworm/main armhf file armhf 1:5.44-3 [41.5 kB] Dec 19 16:08:23 volumio-4 volumio[2612]: info: Get:3 http://raspbian.raspberrypi.com/raspbian bookworm/main armhf mailcap all 3.70+nmu1 [32.0 kB] Dec 19 16:08:23 volumio-4 volumio[2612]: info: Get:4 http://ftp.arnes.si/mirrors/raspbian/raspbian bookworm/main armhf mime-support all 3.66 [10.9 kB] Dec 19 16:08:23 volumio-4 volumio[2612]: info: Get:5 http://ftp.arnes.si/mirrors/raspbian/raspbian bookworm/main armhf libimagequant0 armhf 2.17.0-1 [28.0 kB] Dec 19 16:08:23 volumio-4 volumio[2612]: info: Get:6 http://ftp.arnes.si/mirrors/raspbian/raspbian bookworm/main armhf libraqm0 armhf 0.7.0-4.1 [9176 B] Dec 19 16:08:23 volumio-4 volumio[2612]: info: Get:7 http://ftp.arnes.si/mirrors/raspbian/raspbian bookworm/main armhf python3-olefile all 0.46-3 [36.1 kB] Dec 19 16:08:23 volumio-4 volumio[2612]: info: Get:8 http://raspbian.raspberrypi.com/raspbian bookworm/main armhf python3-pil armhf 9.4.0-1.1+deb12u1 [433 kB] Dec 19 16:08:25 volumio-4 volumio[2612]: info: Fetched 638 kB in 2s (277 kB/s) Dec 19 16:08:25 volumio-4 volumio[2612]: info: Selecting previously unselected package bzip2. Dec 19 16:08:25 volumio-4 volumio[2612]: [620B blob data] Dec 19 16:08:25 volumio-4 volumio[2612]: info: Preparing to unpack .../0-bzip2_1.0.8-5+b2_armhf.deb ... Dec 19 16:08:25 volumio-4 volumio[2612]: info: Unpacking bzip2 (1.0.8-5+b2) ... Dec 19 16:08:25 volumio-4 volumio[2612]: info: Selecting previously unselected package file. Dec 19 16:08:25 volumio-4 volumio[2612]: info: Preparing to unpack .../1-file_1%3a5.44-3_armhf.deb ... Dec 19 16:08:25 volumio-4 volumio[2612]: info: Unpacking file (1:5.44-3) ... Dec 19 16:08:25 volumio-4 volumio[2612]: info: Selecting previously unselected package mailcap. Dec 19 16:08:25 volumio-4 volumio[2612]: info: Preparing to unpack .../2-mailcap_3.70+nmu1_all.deb ... Dec 19 16:08:25 volumio-4 volumio[2612]: info: Unpacking mailcap (3.70+nmu1) ... Dec 19 16:08:25 volumio-4 volumio[2612]: info: Selecting previously unselected package mime-support. Dec 19 16:08:25 volumio-4 volumio[2612]: info: Preparing to unpack .../3-mime-support_3.66_all.deb ... Dec 19 16:08:25 volumio-4 volumio[2612]: info: Unpacking mime-support (3.66) ... Dec 19 16:08:25 volumio-4 volumio[2612]: info: Selecting previously unselected package libimagequant0:armhf. Dec 19 16:08:25 volumio-4 volumio[2612]: info: Preparing to unpack .../4-libimagequant0_2.17.0-1_armhf.deb ... Dec 19 16:08:25 volumio-4 volumio[2612]: info: Unpacking libimagequant0:armhf (2.17.0-1) ... Dec 19 16:08:25 volumio-4 volumio[2612]: info: Selecting previously unselected package libraqm0:armhf. Dec 19 16:08:25 volumio-4 volumio[2612]: info: Preparing to unpack .../5-libraqm0_0.7.0-4.1_armhf.deb ... Dec 19 16:08:25 volumio-4 volumio[2612]: info: Unpacking libraqm0:armhf (0.7.0-4.1) ... Dec 19 16:08:25 volumio-4 volumio[2612]: info: Selecting previously unselected package python3-olefile. Dec 19 16:08:25 volumio-4 volumio[2612]: info: Preparing to unpack .../6-python3-olefile_0.46-3_all.deb ... Dec 19 16:08:25 volumio-4 volumio[2612]: info: Unpacking python3-olefile (0.46-3) ... Dec 19 16:08:25 volumio-4 volumio[2612]: info: Selecting previously unselected package python3-pil:armhf. Dec 19 16:08:25 volumio-4 volumio[2612]: info: Preparing to unpack .../7-python3-pil_9.4.0-1.1+deb12u1_armhf.deb ... Dec 19 16:08:25 volumio-4 volumio[2612]: info: Unpacking python3-pil:armhf (9.4.0-1.1+deb12u1) ... Dec 19 16:08:26 volumio-4 volumio[2612]: info: Setting up python3-olefile (0.46-3) ... Dec 19 16:08:26 volumio-4 volumio[2612]: info: Setting up file (1:5.44-3) ... Dec 19 16:08:26 volumio-4 volumio[2612]: info: Setting up bzip2 (1.0.8-5+b2) ... Dec 19 16:08:26 volumio-4 volumio[2612]: info: Setting up libraqm0:armhf (0.7.0-4.1) ... Dec 19 16:08:26 volumio-4 volumio[2612]: info: Setting up libimagequant0:armhf (2.17.0-1) ... Dec 19 16:08:26 volumio-4 volumio[2612]: info: Setting up mailcap (3.70+nmu1) ... Dec 19 16:08:26 volumio-4 volumio[2612]: info: Setting up mime-support (3.66) ... Dec 19 16:08:26 volumio-4 volumio[2612]: info: Setting up python3-pil:armhf (9.4.0-1.1+deb12u1) ... Dec 19 16:08:27 volumio-4 volumio[2612]: info: Processing triggers for man-db (2.11.2-2) ... Dec 19 16:08:27 volumio-4 volumio[2612]: info: Processing triggers for libc-bin (2.36-9+rpt2+deb12u13) ... Dec 19 16:08:28 volumio-4 sudo[5210]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:28 volumio-4 volumio[2612]: info: Linked /data/plugins/user_interface/peppyspectrum/alsa-lib/armhf/libpeppyalsa.so.0.0.0 to /data/plugins/user_interface/peppyspectrum/alsa-lib/libpeppyalsa.so Dec 19 16:08:28 volumio-4 volumio[2612]: info: Linked /data/plugins/user_interface/peppyspectrum/alsa-lib/armhf/libpeppyalsa.so.0.0.0 to /data/plugins/user_interface/peppyspectrum/alsa-lib/libpeppyalsa.so.0 Dec 19 16:08:28 volumio-4 sudo[5366]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/chmod +x /data/plugins/user_interface/peppyspectrum/startpeppyspectrum.sh Dec 19 16:08:28 volumio-4 sudo[5366]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 19 16:08:28 volumio-4 sudo[5366]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:28 volumio-4 sudo[5368]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/systemctl daemon-reload Dec 19 16:08:28 volumio-4 sudo[5368]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 19 16:08:28 volumio-4 systemd[1]: Reloading. Dec 19 16:08:28 volumio-4 systemd[1]: /etc/systemd/system/musicservicesshield.service:14: Failed to parse output specifier, ignoring: jouurnal Dec 19 16:08:28 volumio-4 systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 19 16:08:28 volumio-4 systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 19 16:08:28 volumio-4 sudo[5368]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:28 volumio-4 volumio[2612]: Plugin install end detected on script Dec 19 16:08:28 volumio-4 sudo[5020]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:28 volumio-4 volumio[2612]: info: Install script completed Dec 19 16:08:28 volumio-4 volumio[2612]: info: Adding reference to registry Dec 19 16:08:28 volumio-4 volumio[2612]: info: Done installing plugin. Dec 19 16:08:28 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 19 16:08:28 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 19 16:08:28 volumio-4 volumio[2612]: info: Folder /tmp/plugins removed Dec 19 16:08:28 volumio-4 volumio[2612]: info: Folder /tmp/downloaded_plugin.zip removed Dec 19 16:08:28 volumio-4 volumio[2612]: info: Folder /data/temp removed Dec 19 16:08:35 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:35+01:00" level=trace msg="sent dealer ping" Dec 19 16:08:35 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:35+01:00" level=trace msg="received dealer pong" Dec 19 16:08:38 volumio-4 volumio[2612]: info: Enabling plugin peppyspectrum Dec 19 16:08:38 volumio-4 volumio[2612]: info: Loading plugin "peppyspectrum"... Dec 19 16:08:38 volumio-4 volumio[2612]: info: Preparing to generate the ALSA configuration file Dec 19 16:08:38 volumio-4 volumio[2612]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 19 16:08:38 volumio-4 volumio[2612]: info: Reading ALSA contributions from plugins. Dec 19 16:08:38 volumio-4 volumio[2612]: info: Asound.conf file written Dec 19 16:08:38 volumio-4 sudo[5405]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Dec 19 16:08:38 volumio-4 sudo[5405]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:38 volumio-4 sudo[5405]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:38 volumio-4 volumio[2612]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Dec 19 16:08:38 volumio-4 volumio[2612]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Dec 19 16:08:38 volumio-4 volumio[2612]: info: Output device has changed, restarting MPD Dec 19 16:08:38 volumio-4 volumio[2612]: info: Output device has changed, restarting Shairport Sync Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 19 16:08:38 volumio-4 sudo[5414]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 19 16:08:38 volumio-4 sudo[5414]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:38 volumio-4 sudo[5413]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 19 16:08:38 volumio-4 sudo[5413]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:38 volumio-4 volumio[2612]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 19 16:08:38 volumio-4 volumio[2612]: info: PLUGIN START: peppyspectrum Dec 19 16:08:38 volumio-4 sudo[5413]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:38 volumio-4 systemd[1]: musicservicesshield.service: Deactivated successfully. Dec 19 16:08:38 volumio-4 systemd[1]: Stopped musicservicesshield.service - Shield Volumio Music Services in the User CPU Set. Dec 19 16:08:38 volumio-4 systemd[1]: Stopping musicservicesshield.service - Shield Volumio Music Services in the User CPU Set... Dec 19 16:08:38 volumio-4 systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 19 16:08:38 volumio-4 volumio[2612]: info: Preparing to generate the ALSA configuration file Dec 19 16:08:38 volumio-4 sudo[5424]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/modprobe snd-aloop index=7 pcm_substreams=1 Dec 19 16:08:38 volumio-4 sudo[5424]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:38 volumio-4 systemd[1]: mpd.service: Deactivated successfully. Dec 19 16:08:38 volumio-4 systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 19 16:08:38 volumio-4 systemd[1]: mpd.service: Consumed 10.883s CPU time. Dec 19 16:08:38 volumio-4 systemd[1]: mpd.socket: Deactivated successfully. Dec 19 16:08:38 volumio-4 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 19 16:08:38 volumio-4 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 19 16:08:38 volumio-4 volumio[2612]: info: Done. Dec 19 16:08:38 volumio-4 volumio[2612]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 19 16:08:38 volumio-4 volumio[2612]: info: Reading ALSA contributions from plugins. Dec 19 16:08:38 volumio-4 volumio[2612]: info: MPD Permissions set Dec 19 16:08:38 volumio-4 volumio[2612]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:38 volumio-4 sudo[5424]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:38 volumio-4 volumio[2612]: info: snd_dummy loaded Dec 19 16:08:38 volumio-4 volumio[2612]: info: Starting Shairport Sync Dec 19 16:08:38 volumio-4 (udev-worker)[5436]: controlC7: Process '/usr/sbin/alsactl -E HOME=/run/alsa -E XDG_RUNTIME_DIR=/run/alsa/runtime restore 7' failed with exit code 99. Dec 19 16:08:38 volumio-4 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 19 16:08:38 volumio-4 systemd[1]: Starting mpd.service - Music Player Daemon... Dec 19 16:08:38 volumio-4 sudo[5439]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 19 16:08:38 volumio-4 sudo[5439]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:38 volumio-4 volumio[2612]: info: Asound.conf file unchanged, so no further update is needed Dec 19 16:08:38 volumio-4 volumio[2612]: info: Output device has changed, restarting MPD Dec 19 16:08:38 volumio-4 volumio[2612]: info: Output device has changed, restarting Shairport Sync Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 19 16:08:38 volumio-4 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 19 16:08:38 volumio-4 systemd[1]: shairport-sync.service: Deactivated successfully. Dec 19 16:08:38 volumio-4 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 19 16:08:38 volumio-4 systemd[1]: shairport-sync.service: Consumed 2.284s CPU time. Dec 19 16:08:38 volumio-4 sudo[5444]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 19 16:08:38 volumio-4 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 19 16:08:38 volumio-4 sudo[5439]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:38 volumio-4 sudo[5444]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:38 volumio-4 sudo[5445]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 19 16:08:38 volumio-4 sudo[5445]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:38 volumio-4 volumio[2612]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 19 16:08:38 volumio-4 sudo[5445]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:38 volumio-4 volumio[2612]: info: Shairport-Sync Started Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:38 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:39 volumio-4 systemd[1]: mpd.service: Deactivated successfully. Dec 19 16:08:39 volumio-4 systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 19 16:08:39 volumio-4 systemd[1]: mpd.socket: Deactivated successfully. Dec 19 16:08:39 volumio-4 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 19 16:08:39 volumio-4 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 19 16:08:39 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 19 16:08:39 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:39 volumio-4 volumio[2612]: info: MPD Permissions set Dec 19 16:08:39 volumio-4 volumio[2612]: info: Starting Shairport Sync Dec 19 16:08:39 volumio-4 sudo[5478]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 19 16:08:39 volumio-4 sudo[5478]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:39 volumio-4 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 19 16:08:39 volumio-4 systemd[1]: Starting mpd.service - Music Player Daemon... Dec 19 16:08:39 volumio-4 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 19 16:08:39 volumio-4 systemd[1]: shairport-sync.service: Deactivated successfully. Dec 19 16:08:39 volumio-4 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 19 16:08:39 volumio-4 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 19 16:08:39 volumio-4 sudo[5478]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:39 volumio-4 volumio[2612]: info: Shairport-Sync Started Dec 19 16:08:39 volumio-4 sudo[5480]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 19 16:08:39 volumio-4 sudo[5480]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 19 16:08:39 volumio-4 sudo[5480]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:39 volumio-4 mpd[5497]: 2025-12-19T16:08:39 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 19 16:08:39 volumio-4 systemd[1]: Started mpd.service - Music Player Daemon. Dec 19 16:08:39 volumio-4 sudo[5444]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:39 volumio-4 sudo[5414]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:39 volumio-4 volumio[2612]: error: MPD error: The expression evaluated to a falsy value: Dec 19 16:08:39 volumio-4 volumio[2612]: assert.ok(self.idling) Dec 19 16:08:39 volumio-4 volumio[2612]: error: The expression evaluated to a falsy value: Dec 19 16:08:39 volumio-4 volumio[2612]: assert.ok(self.idling) Dec 19 16:08:39 volumio-4 systemd[1]: Starting musicservicesshield.service - Shield Volumio Music Services in the User CPU Set... Dec 19 16:08:39 volumio-4 volumio[2612]: error: updateQueue error: null Dec 19 16:08:40 volumio-4 bash[5514]: cset: --> shielding system active with Dec 19 16:08:40 volumio-4 bash[5514]: cset: "system" cpuset of CPUSPEC(1-3) with 260 tasks running Dec 19 16:08:40 volumio-4 bash[5514]: cset: "user" cpuset of CPUSPEC(0) with 3 tasks running Dec 19 16:08:40 volumio-4 systemd[1]: Finished musicservicesshield.service - Shield Volumio Music Services in the User CPU Set. Dec 19 16:08:42 volumio-4 sudo[5530]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 19 16:08:42 volumio-4 sudo[5530]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:42 volumio-4 sudo[5533]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 19 16:08:42 volumio-4 sudo[5533]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:42 volumio-4 systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 19 16:08:42 volumio-4 systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 19 16:08:42 volumio-4 systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 19 16:08:42 volumio-4 systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 19 16:08:42 volumio-4 sudo[5530]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:42 volumio-4 mpd_monitor.sh[5535]: MPD Monitor Service: Starting MPD Monitor Service Dec 19 16:08:42 volumio-4 volumio[2612]: info: Successfully started MPD Monitor Dec 19 16:08:42 volumio-4 systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 19 16:08:42 volumio-4 systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 19 16:08:42 volumio-4 systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 19 16:08:42 volumio-4 systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 19 16:08:42 volumio-4 sudo[5533]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:42 volumio-4 mpd_monitor.sh[5538]: MPD Monitor Service: Starting MPD Monitor Service Dec 19 16:08:42 volumio-4 volumio[2612]: info: Successfully started MPD Monitor Dec 19 16:08:44 volumio-4 volumio[2612]: info: Enabling plugin peppyspectrum Dec 19 16:08:44 volumio-4 volumio[2612]: info: Loading plugin "peppyspectrum"... Dec 19 16:08:44 volumio-4 volumio[2612]: info: Preparing to generate the ALSA configuration file Dec 19 16:08:44 volumio-4 volumio[2612]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 19 16:08:44 volumio-4 volumio[2612]: info: Reading ALSA contributions from plugins. Dec 19 16:08:44 volumio-4 volumio[2612]: info: Asound.conf file unchanged, so no further update is needed Dec 19 16:08:44 volumio-4 volumio[2612]: info: Output device has changed, restarting MPD Dec 19 16:08:44 volumio-4 volumio[2612]: info: Output device has changed, restarting Shairport Sync Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 19 16:08:44 volumio-4 sudo[5544]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 19 16:08:44 volumio-4 sudo[5544]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:44 volumio-4 sudo[5546]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 19 16:08:44 volumio-4 sudo[5546]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:44 volumio-4 volumio[2612]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 19 16:08:44 volumio-4 volumio[2612]: info: PLUGIN START: peppyspectrum Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 19 16:08:44 volumio-4 volumio[2612]: info: Preparing to generate the ALSA configuration file Dec 19 16:08:44 volumio-4 systemd[1]: musicservicesshield.service: Deactivated successfully. Dec 19 16:08:44 volumio-4 systemd[1]: Stopped musicservicesshield.service - Shield Volumio Music Services in the User CPU Set. Dec 19 16:08:44 volumio-4 sudo[5544]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:44 volumio-4 systemd[1]: Stopping musicservicesshield.service - Shield Volumio Music Services in the User CPU Set... Dec 19 16:08:44 volumio-4 systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 19 16:08:44 volumio-4 sudo[5554]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/modprobe snd-aloop index=7 pcm_substreams=1 Dec 19 16:08:44 volumio-4 sudo[5554]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:44 volumio-4 volumio[2612]: info: Done. Dec 19 16:08:44 volumio-4 sudo[5554]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:44 volumio-4 volumio[2612]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 19 16:08:44 volumio-4 volumio[2612]: info: Reading ALSA contributions from plugins. Dec 19 16:08:44 volumio-4 volumio[2612]: info: MPD Permissions set Dec 19 16:08:44 volumio-4 volumio[2612]: info: snd_dummy loaded Dec 19 16:08:44 volumio-4 volumio[2612]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 systemd[1]: mpd.service: Deactivated successfully. Dec 19 16:08:44 volumio-4 systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 19 16:08:44 volumio-4 systemd[1]: mpd.socket: Deactivated successfully. Dec 19 16:08:44 volumio-4 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 19 16:08:44 volumio-4 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: Starting Shairport Sync Dec 19 16:08:44 volumio-4 sudo[5563]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 19 16:08:44 volumio-4 sudo[5563]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:44 volumio-4 volumio[2612]: info: Asound.conf file unchanged, so no further update is needed Dec 19 16:08:44 volumio-4 volumio[2612]: info: Output device has changed, restarting MPD Dec 19 16:08:44 volumio-4 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 19 16:08:44 volumio-4 systemd[1]: Starting mpd.service - Music Player Daemon... Dec 19 16:08:44 volumio-4 volumio[2612]: info: Output device has changed, restarting Shairport Sync Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 19 16:08:44 volumio-4 sudo[5566]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 19 16:08:44 volumio-4 sudo[5566]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:44 volumio-4 sudo[5566]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:44 volumio-4 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 19 16:08:44 volumio-4 sudo[5569]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 19 16:08:44 volumio-4 sudo[5569]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:44 volumio-4 systemd[1]: shairport-sync.service: Deactivated successfully. Dec 19 16:08:44 volumio-4 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 19 16:08:44 volumio-4 systemd[1]: shairport-sync.service: Consumed 1.525s CPU time. Dec 19 16:08:44 volumio-4 volumio[2612]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 19 16:08:44 volumio-4 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 19 16:08:44 volumio-4 sudo[5563]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:44 volumio-4 volumio[2612]: info: MPD Permissions set Dec 19 16:08:44 volumio-4 volumio[2612]: info: Shairport-Sync Started Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 systemd[1]: mpd.service: Deactivated successfully. Dec 19 16:08:44 volumio-4 systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 19 16:08:44 volumio-4 systemd[1]: mpd.socket: Deactivated successfully. Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 19 16:08:44 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:08:44 volumio-4 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 19 16:08:44 volumio-4 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 19 16:08:44 volumio-4 volumio[2612]: info: Starting Shairport Sync Dec 19 16:08:44 volumio-4 sudo[5601]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 19 16:08:44 volumio-4 sudo[5601]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:44 volumio-4 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 19 16:08:44 volumio-4 systemd[1]: Starting mpd.service - Music Player Daemon... Dec 19 16:08:44 volumio-4 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 19 16:08:44 volumio-4 systemd[1]: shairport-sync.service: Deactivated successfully. Dec 19 16:08:44 volumio-4 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 19 16:08:44 volumio-4 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 19 16:08:44 volumio-4 sudo[5601]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:44 volumio-4 volumio[2612]: info: Shairport-Sync Started Dec 19 16:08:44 volumio-4 sudo[5603]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 19 16:08:44 volumio-4 sudo[5603]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 19 16:08:44 volumio-4 sudo[5603]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:45 volumio-4 mpd[5620]: 2025-12-19T16:08:45 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 19 16:08:45 volumio-4 systemd[1]: Started mpd.service - Music Player Daemon. Dec 19 16:08:45 volumio-4 sudo[5546]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:45 volumio-4 sudo[5569]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:45 volumio-4 volumio[2612]: error: MPD error: The expression evaluated to a falsy value: Dec 19 16:08:45 volumio-4 volumio[2612]: assert.ok(self.idling) Dec 19 16:08:45 volumio-4 volumio[2612]: error: The expression evaluated to a falsy value: Dec 19 16:08:45 volumio-4 volumio[2612]: assert.ok(self.idling) Dec 19 16:08:45 volumio-4 volumio[2612]: error: updateQueue error: null Dec 19 16:08:45 volumio-4 systemd[1]: Starting musicservicesshield.service - Shield Volumio Music Services in the User CPU Set... Dec 19 16:08:45 volumio-4 bash[5637]: cset: --> shielding system active with Dec 19 16:08:45 volumio-4 bash[5637]: cset: "system" cpuset of CPUSPEC(1-3) with 256 tasks running Dec 19 16:08:45 volumio-4 bash[5637]: cset: "user" cpuset of CPUSPEC(0) with 3 tasks running Dec 19 16:08:45 volumio-4 systemd[1]: Finished musicservicesshield.service - Shield Volumio Music Services in the User CPU Set. Dec 19 16:08:45 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:45+01:00" level=trace msg="emitting websocket event: not_playing" Dec 19 16:08:45 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:45+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4p0XPFssN6vgbyDj7V9IP6" Dec 19 16:08:45 volumio-4 volumio[2612]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:artist:2GTIa7Clthfpu7hivToeD4","uri":"spotify:track:4YflgfU9jCknPCZ0LJI33U","play_origin":""}} Dec 19 16:08:45 volumio-4 volumio[2612]: error: Failed to decode event: not_playing Dec 19 16:08:45 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:45+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 19 16:08:45 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:45+01:00" level=trace msg="emitting websocket event: will_play" Dec 19 16:08:45 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:45+01:00" level=info msg="loaded track \"Saudade da Bahia\" (paused: false, position: 0ms, duration: 196760ms, prefetched: true)" uri="spotify:track:4p0XPFssN6vgbyDj7V9IP6" Dec 19 16:08:45 volumio-4 volumio[2612]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:artist:2GTIa7Clthfpu7hivToeD4","uri":"spotify:track:4p0XPFssN6vgbyDj7V9IP6","play_origin":""}} Dec 19 16:08:45 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:45+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 19 16:08:45 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:45+01:00" level=trace msg="scheduling prefetch in 167s" Dec 19 16:08:45 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:45+01:00" level=trace msg="emitting websocket event: metadata" Dec 19 16:08:45 volumio-4 volumio[2612]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4p0XPFssN6vgbyDj7V9IP6","name":"Saudade da Bahia","artist_names":["Gabriel Santiago"],"album_name":"Momentum","album_cover_url":"https://i.scdn.co/image/ab67616d00001e022ce2b1ca4190f1dc6f62b0e0","position":0,"duration":196760,"release_date":"year:2016 month:5 day:25","track_number":1,"disc_number":1}} Dec 19 16:08:46 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:46+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 19 16:08:46 volumio-4 go-librespot[2954]: time="2025-12-19T16:08:46+01:00" level=trace msg="emitting websocket event: playing" Dec 19 16:08:46 volumio-4 volumio[2612]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:artist:2GTIa7Clthfpu7hivToeD4","uri":"spotify:track:4p0XPFssN6vgbyDj7V9IP6","resume":false,"play_origin":""}} Dec 19 16:08:46 volumio-4 volumio[2612]: SPOTIFY: PUSH STATE SPOTIFY Dec 19 16:08:46 volumio-4 volumio[2612]: SPOTIFY: {"status":"play","service":"spop","title":"Saudade da Bahia","artist":"Gabriel Santiago","album":"Momentum","albumart":"https://i.scdn.co/image/ab67616d00001e022ce2b1ca4190f1dc6f62b0e0","uri":"spotify:track:4p0XPFssN6vgbyDj7V9IP6","trackType":"spotify","seek":0,"duration":196,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 19 16:08:46 volumio-4 volumio[2612]: info: CoreCommandRouter::servicePushState Dec 19 16:08:46 volumio-4 volumio[2612]: info: CoreStateMachine::pushState Dec 19 16:08:46 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 19 16:08:46 volumio-4 volumio[2612]: info: CoreCommandRouter::volumioPushState Dec 19 16:08:46 volumio-4 volumio[2612]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 19 16:08:46 volumio-4 volumio[2612]: info: PeppySpectrum ---peppyspectrum status play Dec 19 16:08:46 volumio-4 sudo[5639]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppyspectrum.service Dec 19 16:08:46 volumio-4 sudo[5639]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:46 volumio-4 systemd[1]: Started peppyspectrum.service - peppyspectrum Daemon. Dec 19 16:08:46 volumio-4 sudo[5639]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:46 volumio-4 volumio[2612]: info: peppyspectrum Daemon Started Dec 19 16:08:46 volumio-4 volumio[2612]: SPOTIFY: PUSH STATE SPOTIFY Dec 19 16:08:46 volumio-4 volumio[2612]: SPOTIFY: {"status":"play","service":"spop","title":"Saudade da Bahia","artist":"Gabriel Santiago","album":"Momentum","albumart":"https://i.scdn.co/image/ab67616d00001e022ce2b1ca4190f1dc6f62b0e0","uri":"spotify:track:4p0XPFssN6vgbyDj7V9IP6","trackType":"spotify","seek":0,"duration":196,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 19 16:08:46 volumio-4 volumio[2612]: info: CoreCommandRouter::servicePushState Dec 19 16:08:46 volumio-4 volumio[2612]: info: CoreStateMachine::pushState Dec 19 16:08:46 volumio-4 volumio[2612]: info: CoreCommandRouter::volumioPushState Dec 19 16:08:46 volumio-4 volumio[2612]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 19 16:08:46 volumio-4 volumio[2612]: info: PeppySpectrum ---peppyspectrum status play Dec 19 16:08:46 volumio-4 volumio[2612]: info: PeppySpectrum ---peppyspectrum status play Dec 19 16:08:46 volumio-4 sudo[5644]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppyspectrum.service Dec 19 16:08:46 volumio-4 sudo[5646]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppyspectrum.service Dec 19 16:08:46 volumio-4 sudo[5644]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:46 volumio-4 sudo[5646]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:46 volumio-4 sudo[5646]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:46 volumio-4 volumio[2612]: info: peppyspectrum Daemon Started Dec 19 16:08:46 volumio-4 sudo[5644]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:46 volumio-4 volumio[2612]: info: peppyspectrum Daemon Started Dec 19 16:08:46 volumio-4 systemd[1]: peppyspectrum.service: Deactivated successfully. Dec 19 16:08:48 volumio-4 sudo[5650]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 19 16:08:48 volumio-4 sudo[5650]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:48 volumio-4 sudo[5652]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 19 16:08:48 volumio-4 sudo[5652]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:08:48 volumio-4 systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 19 16:08:48 volumio-4 systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 19 16:08:48 volumio-4 systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 19 16:08:48 volumio-4 systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 19 16:08:48 volumio-4 sudo[5652]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:48 volumio-4 mpd_monitor.sh[5655]: MPD Monitor Service: Starting MPD Monitor Service Dec 19 16:08:48 volumio-4 sudo[5650]: pam_unix(sudo:session): session closed for user root Dec 19 16:08:48 volumio-4 volumio[2612]: info: Successfully started MPD Monitor Dec 19 16:08:48 volumio-4 volumio[2612]: info: Successfully started MPD Monitor Dec 19 16:08:54 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 19 16:08:54 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 19 16:09:00 volumio-4 go-librespot[2954]: time="2025-12-19T16:09:00+01:00" level=debug msg="fetched chunk 4/13, size: 524288" uri="spotify:track:4p0XPFssN6vgbyDj7V9IP6" Dec 19 16:09:00 volumio-4 volumio[2612]: info: Enabling plugin peppymeterbasic Dec 19 16:09:00 volumio-4 volumio[2612]: info: Loading plugin "peppymeterbasic"... Dec 19 16:09:00 volumio-4 volumio[2612]: info: Preparing to generate the ALSA configuration file Dec 19 16:09:00 volumio-4 volumio[2612]: info: The plugin peppymeterbasic has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 19 16:09:00 volumio-4 volumio[2612]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 19 16:09:00 volumio-4 volumio[2612]: info: Reading ALSA contributions from plugins. Dec 19 16:09:00 volumio-4 volumio[2612]: info: Asound.conf file written Dec 19 16:09:00 volumio-4 sudo[5679]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Dec 19 16:09:00 volumio-4 sudo[5679]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:09:00 volumio-4 sudo[5679]: pam_unix(sudo:session): session closed for user root Dec 19 16:09:00 volumio-4 volumio[2612]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Dec 19 16:09:00 volumio-4 volumio[2612]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Dec 19 16:09:00 volumio-4 volumio[2612]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:7 use case configuration -2 Dec 19 16:09:00 volumio-4 volumio[2612]: No state is present for card Loopback Dec 19 16:09:00 volumio-4 volumio[2612]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:7 use case configuration -2 Dec 19 16:09:00 volumio-4 volumio[2612]: Found hardware: "Loopback" "Loopback Mixer" "" "" "" Dec 19 16:09:00 volumio-4 volumio[2612]: Hardware is initialized using a generic method Dec 19 16:09:00 volumio-4 volumio[2612]: No state is present for card Loopback Dec 19 16:09:00 volumio-4 volumio[2612]: info: Output device has changed, restarting MPD Dec 19 16:09:00 volumio-4 volumio[2612]: info: Output device has changed, restarting Shairport Sync Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 19 16:09:00 volumio-4 sudo[5685]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 19 16:09:00 volumio-4 sudo[5685]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:09:00 volumio-4 sudo[5685]: pam_unix(sudo:session): session closed for user root Dec 19 16:09:00 volumio-4 volumio[2612]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 19 16:09:00 volumio-4 volumio[2612]: info: PLUGIN START: peppymeterbasic Dec 19 16:09:00 volumio-4 sudo[5687]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 19 16:09:00 volumio-4 sudo[5687]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 19 16:09:00 volumio-4 volumio[2612]: info: Preparing to generate the ALSA configuration file Dec 19 16:09:00 volumio-4 volumio[2612]: info: Done. Dec 19 16:09:00 volumio-4 systemd[1]: musicservicesshield.service: Deactivated successfully. Dec 19 16:09:00 volumio-4 systemd[1]: Stopped musicservicesshield.service - Shield Volumio Music Services in the User CPU Set. Dec 19 16:09:00 volumio-4 systemd[1]: Stopping musicservicesshield.service - Shield Volumio Music Services in the User CPU Set... Dec 19 16:09:00 volumio-4 systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 19 16:09:00 volumio-4 volumio[2612]: info: The plugin peppymeterbasic has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 19 16:09:00 volumio-4 volumio[2612]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 19 16:09:00 volumio-4 volumio[2612]: info: Reading ALSA contributions from plugins. Dec 19 16:09:00 volumio-4 volumio[2612]: info: MPD Permissions set Dec 19 16:09:00 volumio-4 volumio[2612]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11 Dec 19 16:09:00 volumio-4 sudo[5695]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/modprobe snd_aloop index=7 pcm_substreams=2 Dec 19 16:09:00 volumio-4 sudo[5695]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:09:00 volumio-4 sudo[5695]: pam_unix(sudo:session): session closed for user root Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 systemd[1]: Starting systemd-tmpfiles-clean.service - Cleanup of Temporary Directories... Dec 19 16:09:00 volumio-4 systemd[1]: mpd.service: Deactivated successfully. Dec 19 16:09:00 volumio-4 systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 19 16:09:00 volumio-4 systemd[1]: mpd.socket: Deactivated successfully. Dec 19 16:09:00 volumio-4 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 19 16:09:00 volumio-4 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 19 16:09:00 volumio-4 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 19 16:09:00 volumio-4 systemd[1]: Starting mpd.service - Music Player Daemon... Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 systemd[1]: systemd-tmpfiles-clean.service: Deactivated successfully. Dec 19 16:09:00 volumio-4 volumio[2612]: info: snd_dummy loaded Dec 19 16:09:00 volumio-4 systemd[1]: Finished systemd-tmpfiles-clean.service - Cleanup of Temporary Directories. Dec 19 16:09:00 volumio-4 volumio[2612]: info: Starting Shairport Sync Dec 19 16:09:00 volumio-4 systemd[1]: run-credentials-systemd\x2dtmpfiles\x2dclean.service.mount: Deactivated successfully. Dec 19 16:09:00 volumio-4 volumio[2612]: info: Asound.conf file unchanged, so no further update is needed Dec 19 16:09:00 volumio-4 volumio[2612]: info: Output device has changed, restarting MPD Dec 19 16:09:00 volumio-4 sudo[5710]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 19 16:09:00 volumio-4 sudo[5710]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:09:00 volumio-4 volumio[2612]: info: Output device has changed, restarting Shairport Sync Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 19 16:09:00 volumio-4 sudo[5714]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 19 16:09:00 volumio-4 sudo[5714]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:09:00 volumio-4 sudo[5714]: pam_unix(sudo:session): session closed for user root Dec 19 16:09:00 volumio-4 sudo[5716]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 19 16:09:00 volumio-4 sudo[5716]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:09:00 volumio-4 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 19 16:09:00 volumio-4 volumio[2612]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 19 16:09:00 volumio-4 systemd[1]: shairport-sync.service: Deactivated successfully. Dec 19 16:09:00 volumio-4 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 19 16:09:00 volumio-4 systemd[1]: shairport-sync.service: Consumed 1.537s CPU time. Dec 19 16:09:00 volumio-4 volumio[2612]: info: MPD Permissions set Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 19 16:09:00 volumio-4 volumio[2612]: info: Starting Shairport Sync Dec 19 16:09:00 volumio-4 sudo[5733]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 19 16:09:00 volumio-4 sudo[5733]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:09:00 volumio-4 sudo[5706]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 19 16:09:00 volumio-4 sudo[5706]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 19 16:09:00 volumio-4 sudo[5706]: pam_unix(sudo:session): session closed for user root Dec 19 16:09:00 volumio-4 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 19 16:09:00 volumio-4 sudo[5710]: pam_unix(sudo:session): session closed for user root Dec 19 16:09:00 volumio-4 volumio[2612]: info: Shairport-Sync Started Dec 19 16:09:00 volumio-4 systemd[1]: mpd.service: Deactivated successfully. Dec 19 16:09:00 volumio-4 systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 19 16:09:00 volumio-4 systemd[1]: mpd.socket: Deactivated successfully. Dec 19 16:09:00 volumio-4 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 19 16:09:00 volumio-4 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 19 16:09:00 volumio-4 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 19 16:09:00 volumio-4 systemd[1]: Starting mpd.service - Music Player Daemon... Dec 19 16:09:00 volumio-4 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 19 16:09:00 volumio-4 systemd[1]: shairport-sync.service: Deactivated successfully. Dec 19 16:09:00 volumio-4 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 19 16:09:00 volumio-4 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 19 16:09:00 volumio-4 sudo[5733]: pam_unix(sudo:session): session closed for user root Dec 19 16:09:00 volumio-4 volumio[2612]: info: Shairport-Sync Started Dec 19 16:09:00 volumio-4 sudo[5752]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 19 16:09:00 volumio-4 sudo[5752]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 19 16:09:00 volumio-4 sudo[5752]: pam_unix(sudo:session): session closed for user root Dec 19 16:09:01 volumio-4 volumio[2612]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 19 16:09:01 volumio-4 mpd[5769]: 2025-12-19T16:09:01 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 19 16:09:01 volumio-4 systemd[1]: Started mpd.service - Music Player Daemon. Dec 19 16:09:01 volumio-4 sudo[5687]: pam_unix(sudo:session): session closed for user root Dec 19 16:09:01 volumio-4 sudo[5716]: pam_unix(sudo:session): session closed for user root Dec 19 16:09:01 volumio-4 volumio[2612]: error: MPD error: The expression evaluated to a falsy value: Dec 19 16:09:01 volumio-4 volumio[2612]: assert.ok(self.idling) Dec 19 16:09:01 volumio-4 volumio[2612]: error: The expression evaluated to a falsy value: Dec 19 16:09:01 volumio-4 volumio[2612]: assert.ok(self.idling) Dec 19 16:09:01 volumio-4 volumio[2612]: error: updateQueue error: null Dec 19 16:09:01 volumio-4 systemd[1]: Starting musicservicesshield.service - Shield Volumio Music Services in the User CPU Set... Dec 19 16:09:01 volumio-4 bash[5800]: cset: --> shielding system active with Dec 19 16:09:01 volumio-4 bash[5800]: cset: "system" cpuset of CPUSPEC(1-3) with 258 tasks running Dec 19 16:09:01 volumio-4 bash[5800]: cset: "user" cpuset of CPUSPEC(0) with 3 tasks running Dec 19 16:09:01 volumio-4 systemd[1]: Finished musicservicesshield.service - Shield Volumio Music Services in the User CPU Set. Dec 19 16:09:04 volumio-4 sudo[5802]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 19 16:09:04 volumio-4 sudo[5802]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:09:04 volumio-4 sudo[5804]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 19 16:09:04 volumio-4 sudo[5804]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:09:04 volumio-4 systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 19 16:09:04 volumio-4 systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 19 16:09:04 volumio-4 systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 19 16:09:04 volumio-4 systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 19 16:09:04 volumio-4 sudo[5804]: pam_unix(sudo:session): session closed for user root Dec 19 16:09:04 volumio-4 mpd_monitor.sh[5807]: MPD Monitor Service: Starting MPD Monitor Service Dec 19 16:09:04 volumio-4 sudo[5802]: pam_unix(sudo:session): session closed for user root Dec 19 16:09:04 volumio-4 volumio[2612]: info: Successfully started MPD Monitor Dec 19 16:09:04 volumio-4 volumio[2612]: info: Successfully started MPD Monitor Dec 19 16:09:05 volumio-4 go-librespot[2954]: time="2025-12-19T16:09:05+01:00" level=trace msg="received accesspoint ping" Dec 19 16:09:05 volumio-4 go-librespot[2954]: time="2025-12-19T16:09:05+01:00" level=trace msg="received accesspoint pong ack" Dec 19 16:09:05 volumio-4 go-librespot[2954]: time="2025-12-19T16:09:05+01:00" level=trace msg="sent dealer ping" Dec 19 16:09:05 volumio-4 go-librespot[2954]: time="2025-12-19T16:09:05+01:00" level=trace msg="received dealer pong" Dec 19 16:09:08 volumio-4 volumio[2612]: info: CALLMETHOD: user_interface peppymeterbasic savepeppy [object Object] Dec 19 16:09:08 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: peppymeterbasic , savepeppy Dec 19 16:09:08 volumio-4 volumio[2612]: aaaaaaaaaaa 1280,400 Dec 19 16:09:08 volumio-4 volumio[2612]: info: PeppyMeterBasic ---1280400 Dec 19 16:09:08 volumio-4 volumio[2612]: error: Failed callmethod call: TypeError: Cannot read properties of undefined (reading 'then') Dec 19 16:09:08 volumio-4 volumio[2612]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 19 16:09:08 volumio-4 volumio[2612]: info: CoreCommandRouter::Close All Modals sent Dec 19 16:09:10 volumio-4 volumio[2612]: info: CALLMETHOD: user_interface peppymeterbasic savepeppy [object Object] Dec 19 16:09:10 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: peppymeterbasic , savepeppy Dec 19 16:09:10 volumio-4 volumio[2612]: aaaaaaaaaaa 1280,400 Dec 19 16:09:10 volumio-4 volumio[2612]: info: PeppyMeterBasic ---1280400 Dec 19 16:09:10 volumio-4 volumio[2612]: error: Failed callmethod call: TypeError: Cannot read properties of undefined (reading 'then') Dec 19 16:09:10 volumio-4 volumio[2612]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 19 16:09:10 volumio-4 volumio[2612]: info: CoreCommandRouter::Close All Modals sent Dec 19 16:09:14 volumio-4 go-librespot[2954]: time="2025-12-19T16:09:14+01:00" level=debug msg="fetched chunk 5/13, size: 524288" uri="spotify:track:4p0XPFssN6vgbyDj7V9IP6" Dec 19 16:09:15 volumio-4 volumio[2612]: info: CALLMETHOD: user_interface peppymeterbasic savepeppy1 [object Object] Dec 19 16:09:15 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: peppymeterbasic , savepeppy1 Dec 19 16:09:15 volumio-4 volumio[2612]: error: Failed callmethod call: TypeError: Cannot read properties of undefined (reading 'then') Dec 19 16:09:15 volumio-4 volumio[2612]: info: PeppyMeterBasic -----------------------meterrandom Dec 19 16:09:15 volumio-4 volumio[2612]: info: PeppyMeterBasic -----------------------$basefolder Dec 19 16:09:15 volumio-4 volumio[2612]: info: PeppyMeterBasic -----------------------screensize1280x400 Dec 19 16:09:15 volumio-4 volumio[2612]: info: PeppyMeterBasic -----------------------screenwidth Dec 19 16:09:15 volumio-4 volumio[2612]: info: PeppyMeterBasic -----------------------screenheight Dec 19 16:09:15 volumio-4 volumio[2612]: info: PeppyMeterBasic -----------------------metersize30 Dec 19 16:09:15 volumio-4 volumio[2612]: error: PeppyMeterBasic ---Error writing config null Dec 19 16:09:15 volumio-4 sudo[5832]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart peppymeterbasic.service Dec 19 16:09:15 volumio-4 sudo[5832]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 19 16:09:15 volumio-4 systemd[1]: Started peppymeterbasic.service - peppymeterbasic Daemon. Dec 19 16:09:15 volumio-4 sudo[5832]: pam_unix(sudo:session): session closed for user root Dec 19 16:09:15 volumio-4 volumio[2612]: info: peppymeterbasic Daemon Started Dec 19 16:09:15 volumio-4 volumio[2612]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 19 16:09:15 volumio-4 volumio[2612]: info: CoreCommandRouter::Close All Modals sent Dec 19 16:09:16 volumio-4 volumio[5836]: libpng warning: iCCP: known incorrect sRGB profile Dec 19 16:09:16 volumio-4 volumio[5836]: libpng warning: iCCP: known incorrect sRGB profile Dec 19 16:09:16 volumio-4 volumio[5836]: libpng warning: iCCP: known incorrect sRGB profile Dec 19 16:09:28 volumio-4 go-librespot[2954]: time="2025-12-19T16:09:28+01:00" level=debug msg="fetched chunk 6/13, size: 524288" uri="spotify:track:4p0XPFssN6vgbyDj7V9IP6" Dec 19 16:09:29 volumio-4 volumio[2612]: info: CALLMETHOD: user_interface peppymeterbasic updatelist Dec 19 16:09:29 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: peppymeterbasic , updatelist Dec 19 16:09:29 volumio-4 volumio[2612]: info: PeppyMeterBasic --- wget 'https://github.com/balbuze/Meter-peppymeter/raw/main/meterslist.txt' Dec 19 16:09:29 volumio-4 volumio[2612]: --2025-12-19 16:09:29-- https://github.com/balbuze/Meter-peppymeter/raw/main/meterslist.txt Dec 19 16:09:29 volumio-4 volumio[2612]: Resolving github.com (github.com)... 140.82.121.4 Dec 19 16:09:29 volumio-4 volumio[2612]: Connecting to github.com (github.com)|140.82.121.4|:443... connected. Dec 19 16:09:29 volumio-4 volumio[2612]: HTTP request sent, awaiting response... 302 Found Dec 19 16:09:29 volumio-4 volumio[2612]: Location: https://raw.githubusercontent.com/balbuze/Meter-peppymeter/main/meterslist.txt [following] Dec 19 16:09:29 volumio-4 volumio[2612]: --2025-12-19 16:09:29-- https://raw.githubusercontent.com/balbuze/Meter-peppymeter/main/meterslist.txt Dec 19 16:09:29 volumio-4 volumio[2612]: Resolving raw.githubusercontent.com (raw.githubusercontent.com)... 185.199.108.133, 185.199.110.133, 185.199.109.133, ... Dec 19 16:09:29 volumio-4 volumio[2612]: Connecting to raw.githubusercontent.com (raw.githubusercontent.com)|185.199.108.133|:443... connected. Dec 19 16:09:29 volumio-4 volumio[2612]: HTTP request sent, awaiting response... 200 OK Dec 19 16:09:29 volumio-4 volumio[2612]: Length: 362 [text/plain] Dec 19 16:09:29 volumio-4 volumio[2612]: Saving to: ‘/data/plugins/user_interface/peppymeterbasic/meterslist.txt’ Dec 19 16:09:29 volumio-4 volumio[2612]: 0K 100% 537K=0.001s Dec 19 16:09:29 volumio-4 volumio[2612]: 2025-12-19 16:09:29 (537 KB/s) - ‘/data/plugins/user_interface/peppymeterbasic/meterslist.txt’ saved [362/362] Dec 19 16:09:29 volumio-4 volumio[2612]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 19 16:09:29 volumio-4 volumio[2612]: info: CoreCommandRouter::Close All Modals sent Dec 19 16:09:35 volumio-4 go-librespot[2954]: time="2025-12-19T16:09:35+01:00" level=trace msg="sent dealer ping" Dec 19 16:09:35 volumio-4 go-librespot[2954]: time="2025-12-19T16:09:35+01:00" level=trace msg="received dealer pong" Dec 19 16:09:36 volumio-4 volumio[5836]: libpng warning: iCCP: known incorrect sRGB profile Dec 19 16:09:36 volumio-4 volumio[5836]: libpng warning: iCCP: known incorrect sRGB profile Dec 19 16:09:36 volumio-4 volumio[5836]: libpng warning: iCCP: known incorrect sRGB profile Dec 19 16:09:42 volumio-4 go-librespot[2954]: time="2025-12-19T16:09:42+01:00" level=debug msg="fetched chunk 7/13, size: 524288" uri="spotify:track:4p0XPFssN6vgbyDj7V9IP6" Dec 19 16:09:47 volumio-4 volumio[2612]: info: CALLMETHOD: user_interface peppymeterbasic dlmeter [object Object] Dec 19 16:09:47 volumio-4 volumio[2612]: info: CoreCommandRouter::executeOnPlugin: peppymeterbasic , dlmeter Dec 19 16:09:48 volumio-4 volumio[2612]: --2025-12-19 16:09:47-- https://github.com/balbuze/Meter-peppymeter/raw/main/Zipped-folders/Choose Dec 19 16:09:48 volumio-4 volumio[2612]: Resolving github.com (github.com)... 140.82.121.4 Dec 19 16:09:48 volumio-4 volumio[2612]: Connecting to github.com (github.com)|140.82.121.4|:443... connected. Dec 19 16:09:48 volumio-4 volumio[2612]: HTTP request sent, awaiting response... 404 Not Found Dec 19 16:09:48 volumio-4 volumio[2612]: 2025-12-19 16:09:48 ERROR 404: Not Found. Dec 19 16:09:48 volumio-4 volumio[2612]: --2025-12-19 16:09:48-- http://a/ Dec 19 16:09:48 volumio-4 volumio[2612]: Resolving a (a)... 127.0.0.1 Dec 19 16:09:48 volumio-4 volumio[2612]: Connecting to a (a)|127.0.0.1|:80... failed: Connection refused. Dec 19 16:09:48 volumio-4 volumio[2612]: --2025-12-19 16:09:48-- http://packet.zip/ Dec 19 16:09:48 volumio-4 volumio[2612]: Resolving packet.zip (packet.zip)... 162.255.119.167 Dec 19 16:09:48 volumio-4 volumio[2612]: Connecting to packet.zip (packet.zip)|162.255.119.167|:80... connected. Dec 19 16:09:48 volumio-4 volumio[2612]: HTTP request sent, awaiting response... 302 Found Dec 19 16:09:48 volumio-4 volumio[2612]: Location: http://www.packet.zip/ [following] Dec 19 16:09:48 volumio-4 volumio[2612]: --2025-12-19 16:09:48-- http://www.packet.zip/ Dec 19 16:09:48 volumio-4 volumio[2612]: Resolving www.packet.zip (www.packet.zip)... 91.195.240.19 Dec 19 16:09:48 volumio-4 volumio[2612]: Connecting to www.packet.zip (www.packet.zip)|91.195.240.19|:80... connected. Dec 19 16:09:48 volumio-4 volumio[2612]: HTTP request sent, awaiting response... 403 Forbidden Dec 19 16:09:48 volumio-4 volumio[2612]: 2025-12-19 16:09:48 ERROR 403: Forbidden. Dec 19 16:09:48 volumio-4 volumio[2612]: error: PeppyMeterBasic --- An error occurs while downloading or installing Meters Dec 19 16:09:48 volumio-4 volumio[2612]: /bin/rm: cannot remove '/tmp/Choose': No such file or directory Dec 19 16:09:48 volumio-4 volumio[2612]: /bin/rm: cannot remove 'a': No such file or directory Dec 19 16:09:48 volumio-4 volumio[2612]: /bin/rm: cannot remove 'packet.zip*': No such file or directory Dec 19 16:09:48 volumio-4 volumio[2612]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 19 16:09:48 volumio-4 volumio[2612]: Error: Command failed: /bin/rm /tmp/Choose a packet.zip* Dec 19 16:09:48 volumio-4 volumio[2612]: /bin/rm: cannot remove '/tmp/Choose': No such file or directory Dec 19 16:09:48 volumio-4 volumio[2612]: /bin/rm: cannot remove 'a': No such file or directory Dec 19 16:09:48 volumio-4 volumio[2612]: /bin/rm: cannot remove 'packet.zip*': No such file or directory Dec 19 16:09:48 volumio-4 volumio[2612]: at checkExecSyncError (node:child_process:887:11) Dec 19 16:09:48 volumio-4 volumio[2612]: at execSync (node:child_process:959:15) Dec 19 16:09:48 volumio-4 volumio[2612]: at /data/plugins/user_interface/peppymeterbasic/index.js:710:19 Dec 19 16:09:48 volumio-4 volumio[2612]: at new Promise () Dec 19 16:09:48 volumio-4 volumio[2612]: at peppymeterbasic.dlmeter (/data/plugins/user_interface/peppymeterbasic/index.js:685:12) Dec 19 16:09:48 volumio-4 volumio[2612]: at CoreCommandRouter.executeOnPlugin (/volumio/app/index.js:1096:32) Dec 19 16:09:48 volumio-4 volumio[2612]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:337:42) Dec 19 16:09:48 volumio-4 volumio[2612]: at Socket.emit (node:events:514:28) Dec 19 16:09:48 volumio-4 volumio[2612]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Dec 19 16:09:48 volumio-4 volumio[2612]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) { Dec 19 16:09:48 volumio-4 volumio[2612]: status: 1, Dec 19 16:09:48 volumio-4 volumio[2612]: signal: null, Dec 19 16:09:48 volumio-4 volumio[2612]: output: [ Dec 19 16:09:48 volumio-4 volumio[2612]: null, Dec 19 16:09:48 volumio-4 volumio[2612]: , Dec 19 16:09:48 volumio-4 volumio[2612]: Dec 19 16:09:48 volumio-4 volumio[2612]: ], Dec 19 16:09:48 volumio-4 volumio[2612]: pid: 5902, Dec 19 16:09:48 volumio-4 volumio[2612]: stdout: , Dec 19 16:09:48 volumio-4 volumio[2612]: stderr: Dec 19 16:09:48 volumio-4 volumio[2612]: } Dec 19 16:09:48 volumio-4 volumio[2612]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 19 16:09:49 volumio-4 sudo[5919]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-19 16:08' Dec 19 16:09:49 volumio-4 sudo[5919]: 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="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"