-- Logs begin at Thu 2019-02-14 10:11:58 GMT, end at Mon 2025-05-12 00:32:55 BST. -- May 12 00:31:00 rhodesrpi volumio[1009]: info: Get:2 http://mirror.mythic-beasts.com/raspbian/raspbian buster/main armhf libgfortran5 armhf 8.3.0-6+rpi1 [206 kB] May 12 00:31:00 rhodesrpi volumio[1009]: info: Get:3 http://mirror.mythic-beasts.com/raspbian/raspbian buster/main armhf libblas3 armhf 3.8.0-2 [103 kB] May 12 00:31:00 rhodesrpi volumio[1009]: info: Get:4 http://mirror.mythic-beasts.com/raspbian/raspbian buster/main armhf libjpeg62-turbo-dev armhf 1:1.5.2-2+deb10u1 [181 kB] May 12 00:31:01 rhodesrpi volumio[1009]: info: Get:5 http://mirror.mythic-beasts.com/raspbian/raspbian buster/main armhf libjpeg-dev all 1:1.5.2-2+deb10u1 [57.7 kB] May 12 00:31:01 rhodesrpi volumio[1009]: info: Get:6 http://mirror.mythic-beasts.com/raspbian/raspbian buster/main armhf liblapack3 armhf 3.8.0-2 [1493 kB] May 12 00:31:01 rhodesrpi volumio[1009]: info: Get:7 http://mirror.mythic-beasts.com/raspbian/raspbian buster/main armhf libportmidi0 armhf 1:217-6 [20.2 kB] May 12 00:31:01 rhodesrpi volumio[1009]: info: Get:8 http://mirror.mythic-beasts.com/raspbian/raspbian buster/main armhf libsdl1.2debian armhf 1.2.15+dfsg2-6~deb10u1 [162 kB] May 12 00:31:01 rhodesrpi volumio[1009]: info: Get:9 http://mirror.mythic-beasts.com/raspbian/raspbian buster/main armhf libsdl-image1.2 armhf 1.2.12-10+deb10u1 [32.8 kB] May 12 00:31:01 rhodesrpi volumio[1009]: info: Get:10 http://mirror.mythic-beasts.com/raspbian/raspbian buster/main armhf libsdl-mixer1.2 armhf 1.2.12-15 [78.0 kB] May 12 00:31:01 rhodesrpi volumio[1009]: info: Get:11 http://mirror.mythic-beasts.com/raspbian/raspbian buster/main armhf libsdl-ttf2.0-0 armhf 2.0.11-6 [17.0 kB] May 12 00:31:02 rhodesrpi volumio[1009]: info: Get:12 http://mirror.mythic-beasts.com/raspbian/raspbian buster/main armhf python3-numpy armhf 1:1.16.2-1 [1873 kB] May 12 00:31:03 rhodesrpi volumio[1009]: info: Get:13 http://mirror.mythic-beasts.com/raspbian/raspbian buster/main armhf python3-pygame armhf 1.9.4.post1+dfsg-3 [534 kB] May 12 00:31:03 rhodesrpi volumio[1009]: info: Get:14 http://mirror.mythic-beasts.com/raspbian/raspbian buster/main armhf timgm6mb-soundfont all 1.3-2 [5421 kB] May 12 00:31:06 rhodesrpi volumio[1009]: info: Fetched 14.5 MB in 6s (2287 kB/s) May 12 00:31:06 rhodesrpi volumio[1009]: info: Selecting previously unselected package fonts-freefont-ttf. May 12 00:31:06 rhodesrpi go-librespot[1405]: time="2025-05-12T00:31:06+01:00" level=debug msg="fetched chunk 7/23, size: 524288" uri="spotify:track:0A9mHc7oYUoCECqByV8cQR" May 12 00:31:07 rhodesrpi volumio[1009]: [620B blob data] May 12 00:31:07 rhodesrpi volumio[1009]: info: Preparing to unpack .../00-fonts-freefont-ttf_20120503-9_all.deb ... May 12 00:31:07 rhodesrpi volumio[1009]: info: Unpacking fonts-freefont-ttf (20120503-9) ... May 12 00:31:08 rhodesrpi volumio[1009]: info: Selecting previously unselected package libgfortran5:armhf. May 12 00:31:08 rhodesrpi volumio[1009]: info: Preparing to unpack .../01-libgfortran5_8.3.0-6+rpi1_armhf.deb ... May 12 00:31:08 rhodesrpi volumio[1009]: info: Unpacking libgfortran5:armhf (8.3.0-6+rpi1) ... May 12 00:31:09 rhodesrpi volumio[1009]: info: Selecting previously unselected package libblas3:armhf. May 12 00:31:09 rhodesrpi volumio[1009]: info: Preparing to unpack .../02-libblas3_3.8.0-2_armhf.deb ... May 12 00:31:09 rhodesrpi volumio[1009]: info: Unpacking libblas3:armhf (3.8.0-2) ... May 12 00:31:09 rhodesrpi volumio[1009]: info: Selecting previously unselected package libjpeg62-turbo-dev:armhf. May 12 00:31:09 rhodesrpi volumio[1009]: info: Preparing to unpack .../03-libjpeg62-turbo-dev_1%3a1.5.2-2+deb10u1_armhf.deb ... May 12 00:31:09 rhodesrpi volumio[1009]: info: Unpacking libjpeg62-turbo-dev:armhf (1:1.5.2-2+deb10u1) ... May 12 00:31:09 rhodesrpi volumio[1009]: info: Selecting previously unselected package libjpeg-dev. May 12 00:31:09 rhodesrpi volumio[1009]: info: Preparing to unpack .../04-libjpeg-dev_1%3a1.5.2-2+deb10u1_all.deb ... May 12 00:31:09 rhodesrpi volumio[1009]: info: Unpacking libjpeg-dev (1:1.5.2-2+deb10u1) ... May 12 00:31:09 rhodesrpi volumio[1009]: info: Selecting previously unselected package liblapack3:armhf. May 12 00:31:09 rhodesrpi volumio[1009]: info: Preparing to unpack .../05-liblapack3_3.8.0-2_armhf.deb ... May 12 00:31:09 rhodesrpi volumio[1009]: info: Unpacking liblapack3:armhf (3.8.0-2) ... May 12 00:31:10 rhodesrpi volumio[1009]: info: Selecting previously unselected package libportmidi0:armhf. May 12 00:31:10 rhodesrpi volumio[1009]: info: Preparing to unpack .../06-libportmidi0_1%3a217-6_armhf.deb ... May 12 00:31:10 rhodesrpi volumio[1009]: info: Unpacking libportmidi0:armhf (1:217-6) ... May 12 00:31:10 rhodesrpi volumio[1009]: info: Selecting previously unselected package libsdl1.2debian:armhf. May 12 00:31:10 rhodesrpi volumio[1009]: info: Preparing to unpack .../07-libsdl1.2debian_1.2.15+dfsg2-6~deb10u1_armhf.deb ... May 12 00:31:10 rhodesrpi volumio[1009]: info: Unpacking libsdl1.2debian:armhf (1.2.15+dfsg2-6~deb10u1) ... May 12 00:31:10 rhodesrpi volumio[1009]: info: Selecting previously unselected package libsdl-image1.2:armhf. May 12 00:31:10 rhodesrpi volumio[1009]: info: Preparing to unpack .../08-libsdl-image1.2_1.2.12-10+deb10u1_armhf.deb ... May 12 00:31:10 rhodesrpi volumio[1009]: info: Unpacking libsdl-image1.2:armhf (1.2.12-10+deb10u1) ... May 12 00:31:10 rhodesrpi volumio[1009]: info: Selecting previously unselected package libsdl-mixer1.2:armhf. May 12 00:31:10 rhodesrpi volumio[1009]: info: Preparing to unpack .../09-libsdl-mixer1.2_1.2.12-15_armhf.deb ... May 12 00:31:10 rhodesrpi volumio[1009]: info: Unpacking libsdl-mixer1.2:armhf (1.2.12-15) ... May 12 00:31:10 rhodesrpi volumio[1009]: info: Selecting previously unselected package libsdl-ttf2.0-0:armhf. May 12 00:31:11 rhodesrpi volumio[1009]: info: Preparing to unpack .../10-libsdl-ttf2.0-0_2.0.11-6_armhf.deb ... May 12 00:31:11 rhodesrpi volumio[1009]: info: Unpacking libsdl-ttf2.0-0:armhf (2.0.11-6) ... May 12 00:31:11 rhodesrpi volumio[1009]: info: Selecting previously unselected package python3-numpy. May 12 00:31:11 rhodesrpi volumio[1009]: info: Preparing to unpack .../11-python3-numpy_1%3a1.16.2-1_armhf.deb ... May 12 00:31:11 rhodesrpi volumio[1009]: info: Unpacking python3-numpy (1:1.16.2-1) ... May 12 00:31:14 rhodesrpi volumio[1009]: info: Selecting previously unselected package python3-pygame. May 12 00:31:14 rhodesrpi go-librespot[1405]: time="2025-05-12T00:31:14+01:00" level=trace msg="sent dealer ping" May 12 00:31:14 rhodesrpi volumio[1009]: info: Preparing to unpack .../12-python3-pygame_1.9.4.post1+dfsg-3_armhf.deb ... May 12 00:31:14 rhodesrpi go-librespot[1405]: time="2025-05-12T00:31:14+01:00" level=trace msg="received dealer pong" May 12 00:31:14 rhodesrpi volumio[1009]: info: Unpacking python3-pygame (1.9.4.post1+dfsg-3) ... May 12 00:31:15 rhodesrpi volumio[1009]: info: Selecting previously unselected package timgm6mb-soundfont. May 12 00:31:15 rhodesrpi volumio[1009]: info: Preparing to unpack .../13-timgm6mb-soundfont_1.3-2_all.deb ... May 12 00:31:15 rhodesrpi volumio[1009]: info: Unpacking timgm6mb-soundfont (1.3-2) ... May 12 00:31:16 rhodesrpi volumio[1009]: info: Setting up fonts-freefont-ttf (20120503-9) ... May 12 00:31:16 rhodesrpi volumio[1009]: info: Setting up libjpeg62-turbo-dev:armhf (1:1.5.2-2+deb10u1) ... May 12 00:31:16 rhodesrpi volumio[1009]: info: Setting up libportmidi0:armhf (1:217-6) ... May 12 00:31:16 rhodesrpi volumio[1009]: info: Setting up libsdl1.2debian:armhf (1.2.15+dfsg2-6~deb10u1) ... May 12 00:31:16 rhodesrpi volumio[1009]: info: Setting up libsdl-mixer1.2:armhf (1.2.12-15) ... May 12 00:31:16 rhodesrpi volumio[1009]: info: Setting up libgfortran5:armhf (8.3.0-6+rpi1) ... May 12 00:31:17 rhodesrpi volumio[1009]: info: Setting up libsdl-ttf2.0-0:armhf (2.0.11-6) ... May 12 00:31:17 rhodesrpi volumio[1009]: info: Setting up timgm6mb-soundfont (1.3-2) ... May 12 00:31:17 rhodesrpi volumio[1009]: info: Setting up libsdl-image1.2:armhf (1.2.12-10+deb10u1) ... May 12 00:31:17 rhodesrpi volumio[1009]: info: Setting up libjpeg-dev (1:1.5.2-2+deb10u1) ... May 12 00:31:17 rhodesrpi volumio[1009]: info: Setting up libblas3:armhf (3.8.0-2) ... May 12 00:31:17 rhodesrpi volumio[1009]: info: update-alternatives: using /usr/lib/arm-linux-gnueabihf/blas/libblas.so.3 to provide /usr/lib/arm-linux-gnueabihf/libblas.so.3 (libblas.so.3-arm-linux-gnueabihf) in auto mode May 12 00:31:17 rhodesrpi volumio[1009]: info: Setting up liblapack3:armhf (3.8.0-2) ... May 12 00:31:17 rhodesrpi volumio[1009]: info: update-alternatives: using /usr/lib/arm-linux-gnueabihf/lapack/liblapack.so.3 to provide /usr/lib/arm-linux-gnueabihf/liblapack.so.3 (liblapack.so.3-arm-linux-gnueabihf) in auto mode May 12 00:31:17 rhodesrpi volumio[1009]: info: Setting up python3-numpy (1:1.16.2-1) ... May 12 00:31:19 rhodesrpi go-librespot[1405]: time="2025-05-12T00:31:19+01:00" level=debug msg="fetched chunk 8/23, size: 524288" uri="spotify:track:0A9mHc7oYUoCECqByV8cQR" May 12 00:31:21 rhodesrpi volumio[1009]: info: Setting up python3-pygame (1.9.4.post1+dfsg-3) ... May 12 00:31:21 rhodesrpi volumio[1009]: info: Processing triggers for libc-bin (2.28-10+rpt2+rpi1+deb10u2) ... May 12 00:31:21 rhodesrpi volumio[1009]: info: Processing triggers for fontconfig (2.13.1-2) ... May 12 00:31:22 rhodesrpi sudo[3060]: pam_unix(sudo:session): session closed for user root May 12 00:31:22 rhodesrpi volumio[1009]: 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 May 12 00:31:22 rhodesrpi volumio[1009]: 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 May 12 00:31:26 rhodesrpi volumio[1009]: info: Looking in indexes: https://pypi.org/simple, https://www.piwheels.org/simple May 12 00:31:26 rhodesrpi volumio[1009]: info: Collecting Pillow May 12 00:31:30 rhodesrpi volumio[1009]: info: Downloading https://www.piwheels.org/simple/pillow/Pillow-9.5.0-cp37-cp37m-linux_armv7l.whl (820kB) May 12 00:31:30 rhodesrpi go-librespot[1405]: time="2025-05-12T00:31:30+01:00" level=debug msg="fetched chunk 9/23, size: 524288" uri="spotify:track:0A9mHc7oYUoCECqByV8cQR" May 12 00:31:31 rhodesrpi volumio[1009]: info: Installing collected packages: Pillow May 12 00:31:32 rhodesrpi volumio[1009]: info: Successfully installed Pillow-9.5.0 May 12 00:31:32 rhodesrpi sudo[3378]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod +x /data/plugins/user_interface/peppyspectrum/startpeppyspectrum.sh May 12 00:31:32 rhodesrpi sudo[3378]: pam_unix(sudo:session): session opened for user root by (uid=0) May 12 00:31:32 rhodesrpi sudo[3378]: pam_unix(sudo:session): session closed for user root May 12 00:31:32 rhodesrpi sudo[2808]: pam_unix(sudo:session): session closed for user root May 12 00:31:32 rhodesrpi volumio[1009]: Plugin install end detected on script May 12 00:31:32 rhodesrpi volumio[1009]: info: Install script completed May 12 00:31:32 rhodesrpi volumio[1009]: info: Adding reference to registry May 12 00:31:32 rhodesrpi volumio[1009]: info: Done installing plugin. May 12 00:31:32 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 12 00:31:32 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 12 00:31:32 rhodesrpi volumio[1009]: info: Folder /tmp/plugins removed May 12 00:31:32 rhodesrpi volumio[1009]: info: Folder /tmp/downloaded_plugin.zip removed May 12 00:31:32 rhodesrpi volumio[1009]: info: Folder /data/temp removed May 12 00:31:38 rhodesrpi volumio[1009]: info: Enabling plugin peppyspectrum May 12 00:31:38 rhodesrpi volumio[1009]: info: Loading plugin "peppyspectrum"... May 12 00:31:38 rhodesrpi volumio[1009]: info: Preparing to generate the ALSA configuration file May 12 00:31:38 rhodesrpi volumio[1009]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf May 12 00:31:38 rhodesrpi volumio[1009]: info: Reading ALSA contributions from plugins. May 12 00:31:38 rhodesrpi volumio[1009]: info: Asound.conf file written May 12 00:31:38 rhodesrpi sudo[3382]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf May 12 00:31:38 rhodesrpi sudo[3382]: pam_unix(sudo:session): session opened for user root by (uid=0) May 12 00:31:38 rhodesrpi sudo[3382]: pam_unix(sudo:session): session closed for user root May 12 00:31:38 rhodesrpi volumio[1009]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:Max Overclock PLL:0' : Device or resource busy May 12 00:31:38 rhodesrpi volumio[1009]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:Max Overclock DSP:0' : Device or resource busy May 12 00:31:38 rhodesrpi volumio[1009]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:Max Overclock DAC:0' : Device or resource busy May 12 00:31:38 rhodesrpi volumio[1009]: info: Output device has changed, restarting MPD May 12 00:31:38 rhodesrpi sudo[3387]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 12 00:31:38 rhodesrpi sudo[3387]: pam_unix(sudo:session): session opened for user root by (uid=0) May 12 00:31:38 rhodesrpi sudo[3387]: pam_unix(sudo:session): session closed for user root May 12 00:31:38 rhodesrpi volumio[1009]: info: Output device has changed, restarting Shairport Sync May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 12 00:31:38 rhodesrpi sudo[3390]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 12 00:31:38 rhodesrpi sudo[3390]: pam_unix(sudo:session): session opened for user root by (uid=0) May 12 00:31:38 rhodesrpi systemd[1]: Stopping Music Player Daemon... May 12 00:31:38 rhodesrpi systemd[1]: mpd.service: Succeeded. May 12 00:31:38 rhodesrpi systemd[1]: Stopped Music Player Daemon. May 12 00:31:38 rhodesrpi volumio[1009]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 12 00:31:38 rhodesrpi volumio[1009]: info: PLUGIN START: peppyspectrum May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile May 12 00:31:38 rhodesrpi volumio[1009]: info: Preparing to generate the ALSA configuration file May 12 00:31:38 rhodesrpi systemd[1]: Starting Music Player Daemon... May 12 00:31:38 rhodesrpi volumio[1009]: info: Done. May 12 00:31:38 rhodesrpi volumio[1009]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf May 12 00:31:38 rhodesrpi volumio[1009]: info: Reading ALSA contributions from plugins. May 12 00:31:38 rhodesrpi volumio[1009]: info: MPD Permissions set May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::volumioGetState May 12 00:31:38 rhodesrpi volumio[1009]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:38 rhodesrpi sudo[3395]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 12 00:31:38 rhodesrpi sudo[3395]: pam_unix(sudo:session): session opened for user root by (uid=0) May 12 00:31:38 rhodesrpi sudo[3395]: pam_unix(sudo:session): session closed for user root May 12 00:31:38 rhodesrpi volumio[1009]: info: Starting Shairport Sync May 12 00:31:38 rhodesrpi volumio[1009]: info: Asound.conf file unchanged, so no further update is needed May 12 00:31:38 rhodesrpi volumio[1009]: info: Output device has changed, restarting MPD May 12 00:31:38 rhodesrpi sudo[3404]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 12 00:31:38 rhodesrpi sudo[3404]: pam_unix(sudo:session): session opened for user root by (uid=0) May 12 00:31:38 rhodesrpi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 12 00:31:38 rhodesrpi systemd[1]: shairport-sync.service: Succeeded. May 12 00:31:38 rhodesrpi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 12 00:31:38 rhodesrpi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 12 00:31:38 rhodesrpi sudo[3407]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 12 00:31:38 rhodesrpi sudo[3404]: pam_unix(sudo:session): session closed for user root May 12 00:31:38 rhodesrpi volumio[1009]: info: Output device has changed, restarting Shairport Sync May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 12 00:31:38 rhodesrpi sudo[3407]: pam_unix(sudo:session): session opened for user root by (uid=0) May 12 00:31:38 rhodesrpi sudo[3407]: pam_unix(sudo:session): session closed for user root May 12 00:31:38 rhodesrpi sudo[3410]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 12 00:31:38 rhodesrpi sudo[3410]: pam_unix(sudo:session): session opened for user root by (uid=0) May 12 00:31:38 rhodesrpi systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM May 12 00:31:38 rhodesrpi systemd[1]: mpd.service: Succeeded. May 12 00:31:38 rhodesrpi systemd[1]: Stopped Music Player Daemon. May 12 00:31:38 rhodesrpi systemd[1]: Starting Music Player Daemon... May 12 00:31:38 rhodesrpi volumio[1009]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 12 00:31:38 rhodesrpi volumio[1009]: info: MPD Permissions set May 12 00:31:38 rhodesrpi volumio[1009]: info: Shairport-Sync Started May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:38 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:39 rhodesrpi sudo[3417]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 12 00:31:39 rhodesrpi sudo[3417]: pam_unix(sudo:session): session opened for user root by (uid=0) May 12 00:31:39 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 12 00:31:39 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:31:39 rhodesrpi sudo[3417]: pam_unix(sudo:session): session closed for user root May 12 00:31:39 rhodesrpi volumio[1009]: info: Starting Shairport Sync May 12 00:31:39 rhodesrpi sudo[3429]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 12 00:31:39 rhodesrpi sudo[3429]: pam_unix(sudo:session): session opened for user root by (uid=0) May 12 00:31:39 rhodesrpi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 12 00:31:39 rhodesrpi systemd[1]: shairport-sync.service: Succeeded. May 12 00:31:39 rhodesrpi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 12 00:31:39 rhodesrpi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 12 00:31:39 rhodesrpi sudo[3429]: pam_unix(sudo:session): session closed for user root May 12 00:31:39 rhodesrpi volumio[1009]: info: Shairport-Sync Started May 12 00:31:39 rhodesrpi mpd[3427]: May 12 00:31 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 12 00:31:39 rhodesrpi systemd[1]: Started Music Player Daemon. May 12 00:31:39 rhodesrpi sudo[3390]: pam_unix(sudo:session): session closed for user root May 12 00:31:39 rhodesrpi sudo[3410]: pam_unix(sudo:session): session closed for user root May 12 00:31:39 rhodesrpi volumio[1009]: error: MPD error: The expression evaluated to a falsy value: May 12 00:31:39 rhodesrpi volumio[1009]: assert.ok(self.idling) May 12 00:31:39 rhodesrpi volumio[1009]: error: The expression evaluated to a falsy value: May 12 00:31:39 rhodesrpi volumio[1009]: assert.ok(self.idling) May 12 00:31:39 rhodesrpi volumio[1009]: error: updateQueue error: null May 12 00:31:41 rhodesrpi volumio[1009]: info: CoreCommandRouter::volumioGetState May 12 00:31:42 rhodesrpi go-librespot[1405]: time="2025-05-12T00:31:42+01:00" level=debug msg="fetched chunk 10/23, size: 524288" uri="spotify:track:0A9mHc7oYUoCECqByV8cQR" May 12 00:31:44 rhodesrpi go-librespot[1405]: time="2025-05-12T00:31:44+01:00" level=trace msg="sent dealer ping" May 12 00:31:44 rhodesrpi go-librespot[1405]: time="2025-05-12T00:31:44+01:00" level=trace msg="received dealer pong" May 12 00:31:46 rhodesrpi volumio[1009]: info: CoreCommandRouter::volumioNext May 12 00:31:46 rhodesrpi volumio[1009]: info: CoreStateMachine::next May 12 00:31:46 rhodesrpi volumio[1009]: info: Spotify next May 12 00:31:46 rhodesrpi volumio[1009]: info: Sending Spotify command to local API: /player/next May 12 00:31:46 rhodesrpi volumio[1009]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request May 12 00:31:47 rhodesrpi volumio[1009]: info: CoreCommandRouter::volumioNext May 12 00:31:47 rhodesrpi volumio[1009]: info: CoreStateMachine::next May 12 00:31:47 rhodesrpi volumio[1009]: info: Spotify next May 12 00:31:47 rhodesrpi volumio[1009]: info: Sending Spotify command to local API: /player/next May 12 00:31:47 rhodesrpi volumio[1009]: error: Failed to send command to Spotify local API: /player/next: Error: Bad Request May 12 00:31:51 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 12 00:31:51 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 12 00:31:54 rhodesrpi go-librespot[1405]: time="2025-05-12T00:31:54+01:00" level=debug msg="fetched chunk 11/23, size: 524288" uri="spotify:track:0A9mHc7oYUoCECqByV8cQR" May 12 00:31:55 rhodesrpi volumio[1009]: info: [yt-cast-receiver] Player.reset() May 12 00:31:55 rhodesrpi volumio[1009]: info: CoreCommandRouter::volumioGetState May 12 00:31:55 rhodesrpi volumio[1009]: info: Disabling plugin ytcr May 12 00:31:55 rhodesrpi volumio[1009]: info: Done. May 12 00:31:56 rhodesrpi volumio[1009]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesYouTube Music May 12 00:31:56 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 12 00:31:56 rhodesrpi volumio[1009]: info: Disabling plugin ytmusic May 12 00:31:56 rhodesrpi volumio[1009]: info: Done. May 12 00:31:57 rhodesrpi volumio[1009]: info: Enabling plugin crossfader_switch May 12 00:31:57 rhodesrpi volumio[1009]: info: Loading plugin "crossfader_switch"... May 12 00:31:58 rhodesrpi volumio[1009]: info: Applying required configuration parameters for plugin crossfader_switch May 12 00:31:58 rhodesrpi volumio[1009]: info: PLUGIN START: crossfader_switch May 12 00:31:58 rhodesrpi volumio[1009]: info: Done. May 12 00:31:58 rhodesrpi volumio[1009]: info: Disabling plugin crossfader_switch May 12 00:31:58 rhodesrpi volumio[1009]: info: Done. May 12 00:32:04 rhodesrpi volumio[1009]: info: Enabling plugin now_playing May 12 00:32:04 rhodesrpi volumio[1009]: info: Loading plugin "now_playing"... May 12 00:32:04 rhodesrpi volumio[1009]: info: PLUGIN START: now_playing May 12 00:32:04 rhodesrpi volumio[1009]: info: [now-playing] ConfigUpdater: config is up to date. May 12 00:32:04 rhodesrpi volumio[1009]: info: [now-playing] App is listening on port 4004. May 12 00:32:04 rhodesrpi volumio[1009]: warn: [now-playing] MyBackgroundMonitor is now watching /data/INTERNAL/NowPlayingPlugin/My Backgrounds May 12 00:32:04 rhodesrpi volumio[1009]: info: Done. May 12 00:32:07 rhodesrpi go-librespot[1405]: time="2025-05-12T00:32:07+01:00" level=debug msg="fetched chunk 12/23, size: 524288" uri="spotify:track:0A9mHc7oYUoCECqByV8cQR" May 12 00:32:12 rhodesrpi volumio[1009]: info: CoreCommandRouter::volumioGetState May 12 00:32:12 rhodesrpi volumio[1009]: info: CorePlayQueue::getTrack 0 May 12 00:32:14 rhodesrpi go-librespot[1405]: time="2025-05-12T00:32:14+01:00" level=trace msg="sent dealer ping" May 12 00:32:14 rhodesrpi go-librespot[1405]: time="2025-05-12T00:32:14+01:00" level=trace msg="received dealer pong" May 12 00:32:16 rhodesrpi volumio[1009]: info: CoreCommandRouter::getUIConfigOnPlugin May 12 00:32:16 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions May 12 00:32:17 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 12 00:32:17 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 12 00:32:17 rhodesrpi volumio[1009]: info: Getting Alsa Cards List without I2S DAC May 12 00:32:17 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SNumber May 12 00:32:17 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 12 00:32:17 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 12 00:32:17 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 12 00:32:17 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 12 00:32:17 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 12 00:32:17 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 12 00:32:17 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 12 00:32:17 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 12 00:32:17 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode May 12 00:32:17 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus May 12 00:32:21 rhodesrpi go-librespot[1405]: time="2025-05-12T00:32:21+01:00" level=debug msg="fetched chunk 13/23, size: 524288" uri="spotify:track:0A9mHc7oYUoCECqByV8cQR" May 12 00:32:33 rhodesrpi go-librespot[1405]: time="2025-05-12T00:32:33+01:00" level=debug msg="fetched chunk 14/23, size: 524288" uri="spotify:track:0A9mHc7oYUoCECqByV8cQR" May 12 00:32:44 rhodesrpi go-librespot[1405]: time="2025-05-12T00:32:44+01:00" level=trace msg="received accesspoint ping" May 12 00:32:44 rhodesrpi go-librespot[1405]: time="2025-05-12T00:32:44+01:00" level=trace msg="received accesspoint pong ack" May 12 00:32:44 rhodesrpi go-librespot[1405]: time="2025-05-12T00:32:44+01:00" level=trace msg="sent dealer ping" May 12 00:32:44 rhodesrpi go-librespot[1405]: time="2025-05-12T00:32:44+01:00" level=trace msg="received dealer pong" May 12 00:32:47 rhodesrpi go-librespot[1405]: time="2025-05-12T00:32:47+01:00" level=debug msg="fetched chunk 15/23, size: 524288" uri="spotify:track:0A9mHc7oYUoCECqByV8cQR" May 12 00:32:52 rhodesrpi volumio[1009]: info: CALLMETHOD: audio_interface alsa_controller saveResamplingOpts [object Object] May 12 00:32:52 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveResamplingOpts May 12 00:32:52 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: mpd , saveResampleOptions May 12 00:32:52 rhodesrpi sudo[3631]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 12 00:32:52 rhodesrpi sudo[3631]: pam_unix(sudo:session): session opened for user root by (uid=0) May 12 00:32:52 rhodesrpi sudo[3631]: pam_unix(sudo:session): session closed for user root May 12 00:32:52 rhodesrpi sudo[3637]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 12 00:32:52 rhodesrpi sudo[3637]: pam_unix(sudo:session): session opened for user root by (uid=0) May 12 00:32:52 rhodesrpi volumio[1009]: info: MPD Permissions set May 12 00:32:52 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:32:52 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:32:52 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:32:52 rhodesrpi systemd[1]: Stopping Music Player Daemon... May 12 00:32:52 rhodesrpi systemd[1]: mpd.service: Succeeded. May 12 00:32:52 rhodesrpi systemd[1]: Stopped Music Player Daemon. May 12 00:32:52 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 12 00:32:52 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 12 00:32:52 rhodesrpi systemd[1]: Starting Music Player Daemon... May 12 00:32:52 rhodesrpi sudo[3643]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 12 00:32:52 rhodesrpi sudo[3643]: pam_unix(sudo:session): session opened for user root by (uid=0) May 12 00:32:52 rhodesrpi sudo[3643]: pam_unix(sudo:session): session closed for user root May 12 00:32:53 rhodesrpi mpd[3647]: May 12 00:32 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 12 00:32:53 rhodesrpi systemd[1]: Started Music Player Daemon. May 12 00:32:53 rhodesrpi sudo[3637]: pam_unix(sudo:session): session closed for user root May 12 00:32:53 rhodesrpi volumio[1009]: error: updateQueue error: null May 12 00:32:54 rhodesrpi volumio[1009]: info: CoreCommandRouter::volumioGetState May 12 00:32:54 rhodesrpi volumio[1009]: info: CorePlayQueue::getTrack 0 May 12 00:32:54 rhodesrpi volumio[1009]: info: CoreCommandRouter::volumioNext May 12 00:32:54 rhodesrpi volumio[1009]: info: CoreStateMachine::next May 12 00:32:54 rhodesrpi volumio[1009]: info: CoreStateMachine::stop May 12 00:32:54 rhodesrpi volumio[1009]: info: CoreStateMachine::setConsumeUpdateService undefined May 12 00:32:54 rhodesrpi volumio[1009]: info: CoreStateMachine::stPlaybackTimer May 12 00:32:54 rhodesrpi volumio[1009]: info: CoreStateMachine::updateTrackBlock May 12 00:32:54 rhodesrpi volumio[1009]: info: CorePlayQueue::getTrackBlock May 12 00:32:54 rhodesrpi volumio[1009]: info: CoreStateMachine::pushState May 12 00:32:54 rhodesrpi volumio[1009]: info: CorePlayQueue::getTrack 0 May 12 00:32:54 rhodesrpi volumio[1009]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 12 00:32:54 rhodesrpi volumio[1009]: info: CoreCommandRouter::volumioPushState May 12 00:32:54 rhodesrpi volumio[1009]: info: CoreStateMachine::serviceStop May 12 00:32:54 rhodesrpi volumio[1009]: info: CorePlayQueue::getTrack 0 May 12 00:32:54 rhodesrpi volumio[1009]: info: CoreCommandRouter::serviceStop May 12 00:32:54 rhodesrpi volumio[1009]: error: WARNING: No stop method for service ytmusic May 12 00:32:54 rhodesrpi volumio[1009]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 12 00:32:54 rhodesrpi volumio[1009]: TypeError: Cannot read property 'then' of undefined May 12 00:32:54 rhodesrpi volumio[1009]: at CoreStateMachine.next (/volumio/app/statemachine.js:1177:9) May 12 00:32:54 rhodesrpi volumio[1009]: at CoreCommandRouter.volumioNext (/volumio/app/index.js:103:28) May 12 00:32:54 rhodesrpi volumio[1009]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:274:26) May 12 00:32:54 rhodesrpi volumio[1009]: at Socket.emit (events.js:315:20) May 12 00:32:54 rhodesrpi volumio[1009]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 May 12 00:32:54 rhodesrpi volumio[1009]: at processTicksAndRejections (internal/process/task_queues.js:75:11) May 12 00:32:54 rhodesrpi volumio[1009]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 12 00:32:55 rhodesrpi sudo[3660]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-12 00:31 May 12 00:32:55 rhodesrpi sudo[3660]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="9ab87de061b3649c303da550e73c92d340b0f989" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 30 Apr 2025 11:47:57 AM CEST" VOLUMIO_VERSION="3.807" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fddd10196af80fdc784c726185a6abe4"