Mar 28 20:23:01 raspberry-pi 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. Mar 28 20:23:01 raspberry-pi 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. Mar 28 20:23:01 raspberry-pi sudo[2382]: pam_unix(sudo:session): session closed for user root Mar 28 20:23:01 raspberry-pi systemd[1]: Reloading. Mar 28 20:23:01 raspberry-pi volumio[1037]: info: touch_display: systemctl daemon-reload succeeded. Mar 28 20:23:01 raspberry-pi sudo[2427]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Mar 28 20:23:01 raspberry-pi sudo[2427]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 20:23:01 raspberry-pi go-librespot[1543]: time="2026-03-28T20:23:01+10:00" level=trace msg="sent dealer ping" Mar 28 20:23:02 raspberry-pi go-librespot[1543]: time="2026-03-28T20:23:02+10:00" level=trace msg="received dealer pong" Mar 28 20:23:02 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Mar 28 20:23:02 raspberry-pi 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. Mar 28 20:23:02 raspberry-pi 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. Mar 28 20:23:03 raspberry-pi sudo[2379]: pam_unix(sudo:session): session closed for user root Mar 28 20:23:03 raspberry-pi volumio[1037]: info: touch_display: systemctl disable getty@tty1.service succeeded. Mar 28 20:23:03 raspberry-pi sudo[2427]: pam_unix(sudo:session): session closed for user root Mar 28 20:23:03 raspberry-pi volumio[1037]: error: touch_display: Failed to start volumio-kiosk.service: Error: Command failed: /usr/bin/sudo /bin/systemctl start volumio-kiosk.service Mar 28 20:23:03 raspberry-pi volumio[1037]: Failed to start volumio-kiosk.service: Unit volumio-kiosk.service not found. Mar 28 20:23:03 raspberry-pi volumio[1037]: info: Error: Error Mar 28 20:23:03 raspberry-pi sudo[2377]: pam_unix(sudo:session): session closed for user root Mar 28 20:23:03 raspberry-pi volumio[1037]: info: touch_display: systemctl stop getty@tty1.service succeeded. Mar 28 20:23:04 raspberry-pi volumio[1037]: info: Enabling plugin touch_display Mar 28 20:23:04 raspberry-pi volumio[1037]: info: Loading plugin "touch_display"... Mar 28 20:23:04 raspberry-pi volumio[1037]: info: Applying required configuration parameters for plugin touch_display Mar 28 20:23:04 raspberry-pi volumio[1037]: info: PLUGIN START: touch_display Mar 28 20:23:04 raspberry-pi volumio[1037]: info: Loading i18n strings for locale en Mar 28 20:23:04 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 20:23:04 raspberry-pi sudo[2451]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /data/volumiokioskextensions/IframeKeyboardBridge Mar 28 20:23:04 raspberry-pi sudo[2451]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 20:23:04 raspberry-pi volumio[1037]: info: touch_display: No backlight interface detected. Mar 28 20:23:04 raspberry-pi sudo[2451]: pam_unix(sudo:session): session closed for user root Mar 28 20:23:04 raspberry-pi sudo[2453]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop getty@tty1.service Mar 28 20:23:04 raspberry-pi sudo[2453]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 20:23:04 raspberry-pi volumio[1037]: info: touch_display: No Raspberry Pi Foundation touch screen detected. Mar 28 20:23:04 raspberry-pi sudo[2455]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl disable getty@tty1.service Mar 28 20:23:04 raspberry-pi sudo[2455]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 20:23:04 raspberry-pi sudo[2458]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Mar 28 20:23:04 raspberry-pi sudo[2458]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 20:23:04 raspberry-pi sudo[2461]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/99-vc4.conf Mar 28 20:23:04 raspberry-pi sudo[2465]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/cp -r /data/plugins/user_interface/touch_display/iframe_keyboard_bridge/content.js /data/plugins/user_interface/touch_display/iframe_keyboard_bridge/manifest.json /data/volumiokioskextensions/IframeKeyboardBridge/ Mar 28 20:23:04 raspberry-pi sudo[2461]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 20:23:04 raspberry-pi sudo[2465]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 20:23:04 raspberry-pi sudo[2465]: pam_unix(sudo:session): session closed for user root Mar 28 20:23:04 raspberry-pi volumio[1037]: info: touch_display: IframeKeyboardBridge extension installed successfully Mar 28 20:23:04 raspberry-pi sudo[2461]: pam_unix(sudo:session): session closed for user root Mar 28 20:23:04 raspberry-pi volumio[1037]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/99-vc4.conf set. Mar 28 20:23:04 raspberry-pi systemd[1]: Reloading. Mar 28 20:23:05 raspberry-pi volumio[1037]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 20:23:05 raspberry-pi volumio[1037]: info: touch_display: About to detect HDMI ports... Mar 28 20:23:05 raspberry-pi volumio[1037]: info: touch_display: X server not ready, cannot detect HDMI ports yet. Mar 28 20:23:05 raspberry-pi 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. Mar 28 20:23:05 raspberry-pi 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. Mar 28 20:23:06 raspberry-pi systemd[1]: Reloading. Mar 28 20:23:06 raspberry-pi sudo[2455]: pam_unix(sudo:session): session closed for user root Mar 28 20:23:06 raspberry-pi volumio[1037]: info: touch_display: systemctl disable getty@tty1.service succeeded. Mar 28 20:23:07 raspberry-pi 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. Mar 28 20:23:07 raspberry-pi 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. Mar 28 20:23:07 raspberry-pi sudo[2458]: pam_unix(sudo:session): session closed for user root Mar 28 20:23:07 raspberry-pi volumio[1037]: info: touch_display: systemctl daemon-reload succeeded. Mar 28 20:23:07 raspberry-pi sudo[2510]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Mar 28 20:23:07 raspberry-pi sudo[2510]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 20:23:07 raspberry-pi sudo[2453]: pam_unix(sudo:session): session closed for user root Mar 28 20:23:07 raspberry-pi volumio[1037]: info: touch_display: systemctl stop getty@tty1.service succeeded. Mar 28 20:23:07 raspberry-pi sudo[2510]: pam_unix(sudo:session): session closed for user root Mar 28 20:23:07 raspberry-pi volumio[1037]: error: touch_display: Failed to start volumio-kiosk.service: Error: Command failed: /usr/bin/sudo /bin/systemctl start volumio-kiosk.service Mar 28 20:23:07 raspberry-pi volumio[1037]: Failed to start volumio-kiosk.service: Unit volumio-kiosk.service not found. Mar 28 20:23:07 raspberry-pi volumio[1037]: info: Error: Error Mar 28 20:23:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 28 20:23:12 raspberry-pi volumio[1037]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Mar 28 20:23:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Mar 28 20:23:12 raspberry-pi volumio[1037]: info: Received Get System Version Mar 28 20:23:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 20:23:12 raspberry-pi volumio[1037]: info: Received Get System Info Mar 28 20:23:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 20:23:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 20:23:12 raspberry-pi volumio[1037]: info: Discovery: Getting this device information Mar 28 20:23:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioGetState Mar 28 20:23:12 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:23:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 20:23:28 raspberry-pi volumio[1037]: info: CALLMETHOD: user_interface touch_display saveVirtualKeyboardConf [object Object] Mar 28 20:23:28 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: touch_display , saveVirtualKeyboardConf Mar 28 20:23:28 raspberry-pi volumio[1037]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 20:23:28 raspberry-pi volumio[1037]: error: touch_display: Virtual keyboard setting cannot be applied: Error: ENOENT: no such file or directory, stat '/tmp/.X11-unix/Xundefined' Mar 28 20:23:28 raspberry-pi volumio[1037]: info: touch_display: About to detect HDMI ports... Mar 28 20:23:28 raspberry-pi volumio[1037]: info: touch_display: X server not ready, cannot detect HDMI ports yet. Mar 28 20:23:30 raspberry-pi go-librespot[1543]: time="2026-03-28T20:23:30+10:00" level=trace msg="received accesspoint ping" Mar 28 20:23:30 raspberry-pi go-librespot[1543]: time="2026-03-28T20:23:30+10:00" level=trace msg="received accesspoint pong ack" Mar 28 20:23:31 raspberry-pi go-librespot[1543]: time="2026-03-28T20:23:31+10:00" level=trace msg="sent dealer ping" Mar 28 20:23:31 raspberry-pi go-librespot[1543]: time="2026-03-28T20:23:31+10:00" level=trace msg="received dealer pong" Mar 28 20:23:34 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 20:23:34 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 28 20:23:47 raspberry-pi volumio[1037]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 20:23:52 raspberry-pi volumio[1037]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 28 20:23:52 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 28 20:23:52 raspberry-pi volumio[1037]: info: Creating Spotify config file Mar 28 20:23:52 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 20:23:52 raspberry-pi volumio[1037]: info: Spotify config file written Mar 28 20:23:52 raspberry-pi sudo[2588]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 28 20:23:52 raspberry-pi sudo[2588]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 20:23:53 raspberry-pi systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 28 20:23:53 raspberry-pi systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 28 20:23:53 raspberry-pi systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 20:23:53 raspberry-pi volumio[1037]: info: Connection to go-librespot Websocket closed Mar 28 20:23:53 raspberry-pi systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 20:23:53 raspberry-pi go-librespot[2590]: go-librespot daemon starting... Mar 28 20:23:53 raspberry-pi sudo[2588]: pam_unix(sudo:session): session closed for user root Mar 28 20:23:53 raspberry-pi go-librespot[2591]: time="2026-03-28T20:23:53+10:00" level=info msg="running go-librespot 0.7.1" Mar 28 20:23:53 raspberry-pi go-librespot[2591]: time="2026-03-28T20:23:53+10:00" level=debug msg="app state loaded" Mar 28 20:23:53 raspberry-pi go-librespot[2591]: time="2026-03-28T20:23:53+10:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 20:23:53 raspberry-pi go-librespot[2591]: time="2026-03-28T20:23:53+10:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 28 20:23:53 raspberry-pi go-librespot[2591]: time="2026-03-28T20:23:53+10:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 28 20:23:53 raspberry-pi go-librespot[2591]: time="2026-03-28T20:23:53+10:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 28 20:23:53 raspberry-pi go-librespot[2591]: time="2026-03-28T20:23:53+10:00" level=info msg="zeroconf server listening on port 39077" Mar 28 20:23:53 raspberry-pi go-librespot[2591]: time="2026-03-28T20:23:53+10:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 28 20:23:54 raspberry-pi go-librespot[2591]: time="2026-03-28T20:23:54+10:00" level=debug msg="obtained new client token: AAAlANp2rK+ACY2Y2/khbPNrPYtISvbIcjguX+A9EyRbOVmmbFCzjNZG+RBiKdc7ArwVDZuHCEygoaUT89S8zAjGDYeaujQsG8fICzRPMVj+UpLKQs4wkl1ncGfubhgq3+HqeWMpjtbKlm115wuRKeCWh2VOBiYCVz2MmQKyP4oVNbC6vV2QobK2Pm1sL34bWx7nJOv9S9tT0HZID4qRmG2Mb6n/fZybI9XGcTePjTROx8bjoVGU7Nt6" Mar 28 20:23:54 raspberry-pi go-librespot[2591]: time="2026-03-28T20:23:54+10:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Mar 28 20:23:54 raspberry-pi go-librespot[2591]: time="2026-03-28T20:23:54+10:00" level=debug msg="connected to ap-gae2.spotify.com:443" Mar 28 20:23:54 raspberry-pi go-librespot[2591]: time="2026-03-28T20:23:54+10:00" level=debug msg="completed keyexchange" Mar 28 20:23:54 raspberry-pi go-librespot[2591]: time="2026-03-28T20:23:54+10:00" level=debug msg="completed challenge" Mar 28 20:23:55 raspberry-pi go-librespot[2591]: time="2026-03-28T20:23:55+10:00" level=info msg="authenticated AP" username="td*********************n0" Mar 28 20:23:55 raspberry-pi volumio[1037]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 28 20:23:55 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 28 20:23:55 raspberry-pi volumio[1037]: info: Creating Spotify config file Mar 28 20:23:55 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 20:23:55 raspberry-pi volumio[1037]: info: Spotify config file written Mar 28 20:23:55 raspberry-pi sudo[2601]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 28 20:23:55 raspberry-pi sudo[2601]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 20:23:55 raspberry-pi systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 28 20:23:55 raspberry-pi systemd[1]: go-librespot-daemon.service: Killing process 2599 (go-librespot) with signal SIGKILL. Mar 28 20:23:55 raspberry-pi systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 28 20:23:55 raspberry-pi systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 20:23:55 raspberry-pi systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 20:23:55 raspberry-pi go-librespot[2603]: go-librespot daemon starting... Mar 28 20:23:55 raspberry-pi sudo[2601]: pam_unix(sudo:session): session closed for user root Mar 28 20:23:55 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:55+10:00" level=info msg="running go-librespot 0.7.1" Mar 28 20:23:55 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:55+10:00" level=debug msg="app state loaded" Mar 28 20:23:55 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:55+10:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 20:23:55 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:55+10:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 28 20:23:55 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:55+10:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 28 20:23:55 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:55+10:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 28 20:23:55 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:55+10:00" level=info msg="zeroconf server listening on port 37451" Mar 28 20:23:55 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:55+10:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 28 20:23:56 raspberry-pi volumio[1037]: info: Initializing connection to go-librespot Websocket Mar 28 20:23:56 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:56+10:00" level=debug msg="new websocket client" Mar 28 20:23:56 raspberry-pi volumio[1037]: info: Connection to go-librespot Websocket established Mar 28 20:23:56 raspberry-pi volumio[1037]: info: go-librespot daemon successfully initialized Mar 28 20:23:56 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:56+10:00" level=debug msg="obtained new client token: AACHSveOYYVozRl9YM+gm/t1U7Nrf2JL73ejzZXW6G0qABmZBHTrgC6hbj2/3ZFoAd4FsZOdj3aP7I55ZIgsYFcRJrsFffYek6vz9aDz6uAuKtKcAPRw0HcVNnMz9xlSr4zKS0AH2Qo7mX1DFgsEzTNEHWgJIW2ctc0kzQj/S5YWHTTLOasStJnKHFb3e1T3aiNcZhVx+Bhdb5oa/DCRh32kgcWyHLLD4mNdPeGn8q/OQ5pxKrDAkVub" Mar 28 20:23:56 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:56+10:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 28 20:23:56 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:56+10:00" level=debug msg="completed keyexchange" Mar 28 20:23:56 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:56+10:00" level=debug msg="completed challenge" Mar 28 20:23:57 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 20:23:57 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 28 20:23:57 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:57+10:00" level=info msg="authenticated AP" username="td*********************n0" Mar 28 20:23:57 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:57+10:00" level=info msg="authenticated Login5" username="td*********************n0" Mar 28 20:23:57 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:57+10:00" level=debug msg="initializing zeroconf session" username="td*********************n0" Mar 28 20:23:58 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:58+10:00" level=debug msg="dealer connection opened" Mar 28 20:23:58 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:58+10:00" level=trace msg="starting accesspoint recv loop" Mar 28 20:23:58 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:58+10:00" level=trace msg="starting dealer recv loop" Mar 28 20:23:58 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:58+10:00" level=trace msg="received accesspoint ping" Mar 28 20:23:58 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:58+10:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 28 20:23:58 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:58+10:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 28 20:23:58 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:58+10:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 28 20:23:58 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:58+10:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 28 20:23:58 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:58+10:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 28 20:23:58 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:58+10:00" level=debug msg="received connection id: ODcyMGE2ZmQtNGVm...MDRGQjk2NEZDQw==" Mar 28 20:23:58 raspberry-pi volumio[1037]: info: go-librespot daemon successfully initialized Mar 28 20:23:58 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:58+10:00" level=trace msg="received accesspoint pong ack" Mar 28 20:23:58 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:58+10:00" level=debug msg="put connect state because NEW_DEVICE" Mar 28 20:23:59 raspberry-pi volumio[1037]: info: Getting Spotify volume Mar 28 20:23:59 raspberry-pi volumio[1037]: info: Spotify volume: 100 Mar 28 20:23:59 raspberry-pi volumio[1037]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Mar 28 20:23:59 raspberry-pi volumio[1037]: info: Initializing connection to go-librespot Websocket Mar 28 20:23:59 raspberry-pi go-librespot[2604]: time="2026-03-28T20:23:59+10:00" level=debug msg="new websocket client" Mar 28 20:23:59 raspberry-pi volumio[1037]: info: Connection to go-librespot Websocket established Mar 28 20:23:59 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioGetState Mar 28 20:23:59 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:23:59 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Mar 28 20:23:59 raspberry-pi volumio[1037]: SPOTIFY: SPOTIFY VOLUME 100 Mar 28 20:23:59 raspberry-pi volumio[1037]: SPOTIFY: VOLUMIO VOLUME 34 Mar 28 20:23:59 raspberry-pi volumio[1037]: SPOTIFY: DELTA VOLUME ENOUGH: true Mar 28 20:23:59 raspberry-pi volumio[1037]: info: Setting Spotify Volume from Volumio: 34 Mar 28 20:24:00 raspberry-pi volumio[1037]: SPOTIFY: SETTING SPOTIFY VOLUME 34 Mar 28 20:24:00 raspberry-pi volumio[1037]: info: Sending Spotify command with payload to local API: /player/volume Mar 28 20:24:00 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:00+10:00" level=debug msg="update volume requested to 22281/65535" Mar 28 20:24:01 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:01+10:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 28 20:24:01 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:01+10:00" level=trace msg="emitting websocket event: volume" Mar 28 20:24:01 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":34,"max":100}} Mar 28 20:24:01 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 34 Mar 28 20:24:01 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":34,"max":100}} Mar 28 20:24:01 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 34 Mar 28 20:24:01 raspberry-pi volumio[1037]: info: Initializing connection to go-librespot Websocket Mar 28 20:24:01 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:01+10:00" level=debug msg="new websocket client" Mar 28 20:24:01 raspberry-pi volumio[1037]: info: Connection to go-librespot Websocket established Mar 28 20:24:02 raspberry-pi volumio[1037]: info: Getting Spotify volume Mar 28 20:24:02 raspberry-pi volumio[1037]: info: Spotify volume: 34 Mar 28 20:24:02 raspberry-pi volumio[1037]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Mar 28 20:24:02 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioGetState Mar 28 20:24:02 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:02 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Mar 28 20:24:03 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:03+10:00" level=debug msg="handling transfer player command from 51332409fb2df8bcb7dc4f4241a3994e859ab5f0" Mar 28 20:24:03 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:03+10:00" level=debug msg="resolved context of track" uri="spotify:album:22aPi3QZtDAXY5EbHdLLmY" Mar 28 20:24:03 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:03+10:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:album:22aPi3QZtDAXY5EbHdLLmY" Mar 28 20:24:03 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:03+10:00" level=debug msg="loading track (paused: true, position: 14696ms)" uri="spotify:track:2GohKE1tNrKUsZPF4ZzrRT" Mar 28 20:24:04 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:04+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 20:24:04 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:04+10:00" level=trace msg="emitting websocket event: will_play" Mar 28 20:24:04 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:album:22aPi3QZtDAXY5EbHdLLmY","uri":"spotify:track:2GohKE1tNrKUsZPF4ZzrRT","play_origin":"album"}} Mar 28 20:24:04 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:album:22aPi3QZtDAXY5EbHdLLmY","uri":"spotify:track:2GohKE1tNrKUsZPF4ZzrRT","play_origin":"album"}} Mar 28 20:24:04 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:album:22aPi3QZtDAXY5EbHdLLmY","uri":"spotify:track:2GohKE1tNrKUsZPF4ZzrRT","play_origin":"album"}} Mar 28 20:24:04 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:04+10:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Mar 28 20:24:04 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:04+10:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1731" Mar 28 20:24:04 raspberry-pi volumio[1037]: info: Getting Spotify volume Mar 28 20:24:04 raspberry-pi volumio[1037]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Mar 28 20:24:04 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioGetState Mar 28 20:24:04 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:04 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Mar 28 20:24:04 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:04+10:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1321" Mar 28 20:24:04 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:04+10:00" level=debug msg="selected format OGG_VORBIS_320 (65b9057d675c079d4ea91ed8f17bf4135145bf16)" uri="spotify:track:2GohKE1tNrKUsZPF4ZzrRT" Mar 28 20:24:04 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:04+10:00" level=debug msg="requested aes key for file 65b9057d675c079d4ea91ed8f17bf4135145bf16, gid: 2GohKE1tNrKUsZPF4ZzrRT" Mar 28 20:24:05 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:05+10:00" level=trace msg="found 2 cdn urls" uri="spotify:track:2GohKE1tNrKUsZPF4ZzrRT" Mar 28 20:24:05 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:05+10:00" level=debug msg="fetched first chunk of 15, total size is 7655053 bytes" uri="spotify:track:2GohKE1tNrKUsZPF4ZzrRT" Mar 28 20:24:05 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:05.687+10:00 level=INFO msg="new address was allocated" component=ble/conn old=2 new=3 Mar 28 20:24:06 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:06+10:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:2GohKE1tNrKUsZPF4ZzrRT" Mar 28 20:24:06 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:06+10:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:2GohKE1tNrKUsZPF4ZzrRT" Mar 28 20:24:07 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:07+10:00" level=debug msg="fetched chunk 4/14, size: 524288" uri="spotify:track:2GohKE1tNrKUsZPF4ZzrRT" Mar 28 20:24:07 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:07+10:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:2GohKE1tNrKUsZPF4ZzrRT" Mar 28 20:24:07 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:07+10:00" level=trace msg="seek to 14696ms (diff: 119ms, samples: 648093, bytes: 589966)" uri="spotify:track:2GohKE1tNrKUsZPF4ZzrRT" Mar 28 20:24:07 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:07+10:00" level=debug msg="created new output device" Mar 28 20:24:07 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:07+10:00" level=info msg="loaded track \"BOBA\" (paused: true, position: 14696ms, duration: 180987ms, prefetched: false)" uri="spotify:track:2GohKE1tNrKUsZPF4ZzrRT" Mar 28 20:24:07 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:07+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 20:24:07 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:07+10:00" level=trace msg="emitting websocket event: metadata" Mar 28 20:24:07 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:07+10:00" level=trace msg="emitting websocket event: active" Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2GohKE1tNrKUsZPF4ZzrRT","name":"BOBA","artist_names":["SOFI TUKKER"],"album_name":"BOBA","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0218285e12126f8ec3956fb6a6","position":14696,"duration":180987,"release_date":"year:2026 month:3 day:13","track_number":1,"disc_number":1}} Mar 28 20:24:07 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:07+10:00" level=debug msg="sending successful reply for dealer request" Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2GohKE1tNrKUsZPF4ZzrRT","name":"BOBA","artist_names":["SOFI TUKKER"],"album_name":"BOBA","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0218285e12126f8ec3956fb6a6","position":14696,"duration":180987,"release_date":"year:2026 month:3 day:13","track_number":1,"disc_number":1}} Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2GohKE1tNrKUsZPF4ZzrRT","name":"BOBA","artist_names":["SOFI TUKKER"],"album_name":"BOBA","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0218285e12126f8ec3956fb6a6","position":14696,"duration":180987,"release_date":"year:2026 month:3 day:13","track_number":1,"disc_number":1}} Mar 28 20:24:07 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:07+10:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 28 20:24:07 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:07+10:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"active","data":null} Mar 28 20:24:07 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:07+10:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 28 20:24:07 raspberry-pi volumio[1037]: info: Aligning Spotify Volume to Volumio Volume Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioGetState Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:07 raspberry-pi volumio[1037]: info: Setting Spotify Volume from Volumio: 34 Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"active","data":null} Mar 28 20:24:07 raspberry-pi volumio[1037]: info: Aligning Spotify Volume to Volumio Volume Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioGetState Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:07 raspberry-pi volumio[1037]: info: Setting Spotify Volume from Volumio: 34 Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"active","data":null} Mar 28 20:24:07 raspberry-pi volumio[1037]: info: Aligning Spotify Volume to Volumio Volume Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioGetState Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:07 raspberry-pi volumio[1037]: info: Setting Spotify Volume from Volumio: 34 Mar 28 20:24:07 raspberry-pi volumio[1037]: info: Spotify volume: 34 Mar 28 20:24:07 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:07+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 20:24:07 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:07+10:00" level=trace msg="emitting websocket event: paused" Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:album:22aPi3QZtDAXY5EbHdLLmY","uri":"spotify:track:2GohKE1tNrKUsZPF4ZzrRT","play_origin":"album"}} Mar 28 20:24:07 raspberry-pi volumio[1037]: info: Spotify is playing in volatile mode Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: UNSET VOLATILE Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: {"status":"stop","position":0,"title":"","artist":"","album":"","albumart":"/albumart","duration":0,"uri":"","seek":0,"samplerate":"","channels":"","bitdepth":"","Streaming":false,"service":"mpd","volume":34,"dbVolume":null,"mute":false,"disableVolumeControl":false,"random":null,"repeat":null,"repeatSingle":false,"updatedb":false,"consume":false} Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: PUSH STATE SPOTIFY Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: {"status":"pause","service":"spop","title":"BOBA","artist":"SOFI TUKKER","album":"BOBA","albumart":"https://i.scdn.co/image/ab67616d00001e0218285e12126f8ec3956fb6a6","uri":"spotify:track:2GohKE1tNrKUsZPF4ZzrRT","trackType":"spotify","seek":14696,"duration":180,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:07 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:07.806+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PAUSED positionMs=14696 volume=34 Mar 28 20:24:07 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:07.808+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PAUSED positionMs=14696 volume=34 Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:album:22aPi3QZtDAXY5EbHdLLmY","uri":"spotify:track:2GohKE1tNrKUsZPF4ZzrRT","play_origin":"album"}} Mar 28 20:24:07 raspberry-pi volumio[1037]: info: Spotify is playing in volatile mode Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: UNSET VOLATILE Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: {"status":"stop","position":0,"title":"","artist":"","album":"","albumart":"/albumart","duration":0,"uri":"","seek":0,"samplerate":"","channels":"","bitdepth":"","Streaming":false,"service":"mpd","volume":34,"dbVolume":null,"mute":false,"disableVolumeControl":false,"random":null,"repeat":null,"repeatSingle":false,"updatedb":false,"consume":false} Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: PUSH STATE SPOTIFY Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: {"status":"pause","service":"spop","title":"BOBA","artist":"SOFI TUKKER","album":"BOBA","albumart":"https://i.scdn.co/image/ab67616d00001e0218285e12126f8ec3956fb6a6","uri":"spotify:track:2GohKE1tNrKUsZPF4ZzrRT","trackType":"spotify","seek":14696,"duration":180,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:07 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:07.838+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PAUSED positionMs=14696 volume=34 Mar 28 20:24:07 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:07.839+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PAUSED positionMs=14696 volume=34 Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:album:22aPi3QZtDAXY5EbHdLLmY","uri":"spotify:track:2GohKE1tNrKUsZPF4ZzrRT","play_origin":"album"}} Mar 28 20:24:07 raspberry-pi volumio[1037]: info: Spotify is playing in volatile mode Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: UNSET VOLATILE Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: {"status":"stop","position":0,"title":"","artist":"","album":"","albumart":"/albumart","duration":0,"uri":"","seek":0,"samplerate":"","channels":"","bitdepth":"","Streaming":false,"service":"mpd","volume":34,"dbVolume":null,"mute":false,"disableVolumeControl":false,"random":null,"repeat":null,"repeatSingle":false,"updatedb":false,"consume":false} Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: PUSH STATE SPOTIFY Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: {"status":"pause","service":"spop","title":"BOBA","artist":"SOFI TUKKER","album":"BOBA","albumart":"https://i.scdn.co/image/ab67616d00001e0218285e12126f8ec3956fb6a6","uri":"spotify:track:2GohKE1tNrKUsZPF4ZzrRT","trackType":"spotify","seek":14696,"duration":180,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:07 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:07 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:07.874+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PAUSED positionMs=14696 volume=34 Mar 28 20:24:07 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:07.875+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PAUSED positionMs=14696 volume=34 Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Mar 28 20:24:07 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Mar 28 20:24:08 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:08.117+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:2GohKE1tNrKUsZPF4ZzrRT title=BOBA Mar 28 20:24:08 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:08.118+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:2GohKE1tNrKUsZPF4ZzrRT title=BOBA Mar 28 20:24:08 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:08.342+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:2GohKE1tNrKUsZPF4ZzrRT title=BOBA Mar 28 20:24:08 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:08.343+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:2GohKE1tNrKUsZPF4ZzrRT title=BOBA Mar 28 20:24:08 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:08+10:00" level=debug msg="handling play player command from 51332409fb2df8bcb7dc4f4241a3994e859ab5f0" Mar 28 20:24:08 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:08+10:00" level=debug msg="resolved context of track" uri="spotify:playlist:4vhzCSV8uqH5Wd6lfSZ4o5" Mar 28 20:24:08 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:08+10:00" level=trace msg="fetched new page 0 with 9 items (list: 9)" uri="spotify:playlist:4vhzCSV8uqH5Wd6lfSZ4o5" Mar 28 20:24:08 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:08+10:00" level=debug msg="shuffled context with seed 3128863068865028069 (len: 9, keep: 7)" uri="spotify:playlist:4vhzCSV8uqH5Wd6lfSZ4o5" Mar 28 20:24:08 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:08+10:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:782EcmrSvkOJw56D6vbNQk" Mar 28 20:24:08 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:08.658+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:2GohKE1tNrKUsZPF4ZzrRT title=BOBA Mar 28 20:24:08 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:08.658+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:2GohKE1tNrKUsZPF4ZzrRT title=BOBA Mar 28 20:24:08 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:08+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 20:24:08 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:08+10:00" level=trace msg="emitting websocket event: will_play" Mar 28 20:24:08 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:4vhzCSV8uqH5Wd6lfSZ4o5","uri":"spotify:track:782EcmrSvkOJw56D6vbNQk","play_origin":"playlist"}} Mar 28 20:24:08 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:4vhzCSV8uqH5Wd6lfSZ4o5","uri":"spotify:track:782EcmrSvkOJw56D6vbNQk","play_origin":"playlist"}} Mar 28 20:24:08 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:4vhzCSV8uqH5Wd6lfSZ4o5","uri":"spotify:track:782EcmrSvkOJw56D6vbNQk","play_origin":"playlist"}} Mar 28 20:24:09 raspberry-pi volumio[1037]: SPOTIFY: SETTING SPOTIFY VOLUME 34 Mar 28 20:24:09 raspberry-pi volumio[1037]: info: Sending Spotify command with payload to local API: /player/volume Mar 28 20:24:09 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:09+10:00" level=debug msg="selected format OGG_VORBIS_320 (466481cf47e223cf3146ccd625b37fe803de20a9)" uri="spotify:track:782EcmrSvkOJw56D6vbNQk" Mar 28 20:24:09 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:09+10:00" level=debug msg="requested aes key for file 466481cf47e223cf3146ccd625b37fe803de20a9, gid: 782EcmrSvkOJw56D6vbNQk" Mar 28 20:24:09 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:09+10:00" level=trace msg="found 2 cdn urls" uri="spotify:track:782EcmrSvkOJw56D6vbNQk" Mar 28 20:24:10 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:10+10:00" level=debug msg="fetched first chunk of 10, total size is 5113760 bytes" uri="spotify:track:782EcmrSvkOJw56D6vbNQk" Mar 28 20:24:10 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:10+10:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Mar 28 20:24:10 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:10+10:00" level=info msg="loaded track \"I Run - Ely Oaks Remix\" (paused: false, position: 0ms, duration: 115236ms, prefetched: false)" uri="spotify:track:782EcmrSvkOJw56D6vbNQk" Mar 28 20:24:10 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:10+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 20:24:10 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:10+10:00" level=trace msg="scheduling prefetch in 85s" Mar 28 20:24:10 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:10+10:00" level=trace msg="emitting websocket event: metadata" Mar 28 20:24:10 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:10+10:00" level=debug msg="sending successful reply for dealer request" Mar 28 20:24:10 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:782EcmrSvkOJw56D6vbNQk","name":"I Run - Ely Oaks Remix","artist_names":["HAVEN.","Kaitlin Aragon","Ely Oaks"],"album_name":"I Run (Ely Oaks Remix)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02381fc8afb081dcf992180142","position":0,"duration":115236,"release_date":"year:2026 month:3 day:6","track_number":1,"disc_number":1}} Mar 28 20:24:10 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:782EcmrSvkOJw56D6vbNQk","name":"I Run - Ely Oaks Remix","artist_names":["HAVEN.","Kaitlin Aragon","Ely Oaks"],"album_name":"I Run (Ely Oaks Remix)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02381fc8afb081dcf992180142","position":0,"duration":115236,"release_date":"year:2026 month:3 day:6","track_number":1,"disc_number":1}} Mar 28 20:24:10 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:782EcmrSvkOJw56D6vbNQk","name":"I Run - Ely Oaks Remix","artist_names":["HAVEN.","Kaitlin Aragon","Ely Oaks"],"album_name":"I Run (Ely Oaks Remix)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02381fc8afb081dcf992180142","position":0,"duration":115236,"release_date":"year:2026 month:3 day:6","track_number":1,"disc_number":1}} Mar 28 20:24:10 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:10+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 20:24:10 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:10+10:00" level=trace msg="emitting websocket event: playing" Mar 28 20:24:10 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:10+10:00" level=debug msg="update volume requested to 22281/65535" Mar 28 20:24:10 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:4vhzCSV8uqH5Wd6lfSZ4o5","uri":"spotify:track:782EcmrSvkOJw56D6vbNQk","resume":false,"play_origin":"playlist"}} Mar 28 20:24:10 raspberry-pi volumio[1037]: SPOTIFY: PUSH STATE SPOTIFY Mar 28 20:24:10 raspberry-pi volumio[1037]: SPOTIFY: {"status":"play","service":"spop","title":"I Run - Ely Oaks Remix","artist":"HAVEN., Kaitlin Aragon, Ely Oaks","album":"I Run (Ely Oaks Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e02381fc8afb081dcf992180142","uri":"spotify:track:782EcmrSvkOJw56D6vbNQk","trackType":"spotify","seek":0,"duration":115,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 28 20:24:10 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:10 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:10+10:00" level=debug msg="update volume requested to 19661/65535" Mar 28 20:24:10 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:10 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 20:24:10 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:10 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:10+10:00" level=debug msg="update volume requested to 22282/65535" Mar 28 20:24:10 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:10.815+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=0 volume=34 Mar 28 20:24:10 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:10.816+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=0 volume=34 Mar 28 20:24:10 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:4vhzCSV8uqH5Wd6lfSZ4o5","uri":"spotify:track:782EcmrSvkOJw56D6vbNQk","resume":false,"play_origin":"playlist"}} Mar 28 20:24:10 raspberry-pi volumio[1037]: SPOTIFY: PUSH STATE SPOTIFY Mar 28 20:24:10 raspberry-pi volumio[1037]: SPOTIFY: {"status":"play","service":"spop","title":"I Run - Ely Oaks Remix","artist":"HAVEN., Kaitlin Aragon, Ely Oaks","album":"I Run (Ely Oaks Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e02381fc8afb081dcf992180142","uri":"spotify:track:782EcmrSvkOJw56D6vbNQk","trackType":"spotify","seek":0,"duration":115,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 28 20:24:10 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:10 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:10 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:10 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:10.844+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=0 volume=34 Mar 28 20:24:10 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:10.846+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=0 volume=34 Mar 28 20:24:10 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:4vhzCSV8uqH5Wd6lfSZ4o5","uri":"spotify:track:782EcmrSvkOJw56D6vbNQk","resume":false,"play_origin":"playlist"}} Mar 28 20:24:10 raspberry-pi volumio[1037]: SPOTIFY: PUSH STATE SPOTIFY Mar 28 20:24:10 raspberry-pi volumio[1037]: SPOTIFY: {"status":"play","service":"spop","title":"I Run - Ely Oaks Remix","artist":"HAVEN., Kaitlin Aragon, Ely Oaks","album":"I Run (Ely Oaks Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e02381fc8afb081dcf992180142","uri":"spotify:track:782EcmrSvkOJw56D6vbNQk","trackType":"spotify","seek":0,"duration":115,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 28 20:24:10 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:10 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:10 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:10 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:10.877+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=0 volume=34 Mar 28 20:24:10 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:10.879+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=0 volume=34 Mar 28 20:24:10 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:10+10:00" level=debug msg="fetched chunk 2/9, size: 524288" uri="spotify:track:782EcmrSvkOJw56D6vbNQk" Mar 28 20:24:10 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Mar 28 20:24:10 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Mar 28 20:24:10 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: PUSH STATE SPOTIFY Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: {"status":"play","service":"spop","title":"I Run - Ely Oaks Remix","artist":"HAVEN., Kaitlin Aragon, Ely Oaks","album":"I Run (Ely Oaks Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e02381fc8afb081dcf992180142","uri":"spotify:track:782EcmrSvkOJw56D6vbNQk","trackType":"spotify","seek":0,"duration":115,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.103+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=0 volume=34 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.104+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=0 volume=34 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: PUSH STATE SPOTIFY Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: {"status":"play","service":"spop","title":"I Run - Ely Oaks Remix","artist":"HAVEN., Kaitlin Aragon, Ely Oaks","album":"I Run (Ely Oaks Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e02381fc8afb081dcf992180142","uri":"spotify:track:782EcmrSvkOJw56D6vbNQk","trackType":"spotify","seek":0,"duration":115,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.136+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.139+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.145+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=0 volume=34 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.145+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=0 volume=34 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: PUSH STATE SPOTIFY Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: {"status":"play","service":"spop","title":"I Run - Ely Oaks Remix","artist":"HAVEN., Kaitlin Aragon, Ely Oaks","album":"I Run (Ely Oaks Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e02381fc8afb081dcf992180142","uri":"spotify:track:782EcmrSvkOJw56D6vbNQk","trackType":"spotify","seek":0,"duration":115,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.188+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=0 volume=34 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.188+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=0 volume=34 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Mar 28 20:24:11 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:11+10:00" level=debug msg="fetched chunk 3/9, size: 524288" uri="spotify:track:782EcmrSvkOJw56D6vbNQk" Mar 28 20:24:11 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:11+10:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 28 20:24:11 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:11+10:00" level=trace msg="emitting websocket event: volume" Mar 28 20:24:11 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:11+10:00" level=debug msg="update volume requested to 24903/65535" Mar 28 20:24:11 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:11+10:00" level=debug msg="update volume requested to 32768/65535" Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":34,"max":100}} Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 34 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":34,"max":100}} Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 34 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":34,"max":100}} Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 34 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.312+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.314+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.493+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.493+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:11 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:11+10:00" level=debug msg="fetched chunk 1/9, size: 524288" uri="spotify:track:782EcmrSvkOJw56D6vbNQk" Mar 28 20:24:11 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:11+10:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 28 20:24:11 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:11+10:00" level=trace msg="emitting websocket event: volume" Mar 28 20:24:11 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:11+10:00" level=debug msg="update volume requested to 43253/65535" Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":50,"max":100}} Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 50 Mar 28 20:24:11 raspberry-pi volumio[1037]: info: Setting Volumio Volume from Spotify: 50 Mar 28 20:24:11 raspberry-pi volumio[1037]: info: VolumeController::SetAlsaVolume50 Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.657+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=0 volume=50 Mar 28 20:24:11 raspberry-pi upmpdcli[1328]: :3:../src/mpdcli.cxx:148::MPDCli::startEventLoop: already started Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.658+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=0 volume=50 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":50,"max":100}} Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 50 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":50,"max":100}} Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 50 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.674+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.679+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:11 raspberry-pi volumio[1037]: info: Mar 28 20:24:11 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:11 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:11 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:11 raspberry-pi volumio[1037]: info: Mar 28 20:24:11 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:11 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:11 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:11 raspberry-pi volumio[1037]: info: Mar 28 20:24:11 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:11 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:11 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:11 raspberry-pi volumio[1037]: info: sendMpdCommand status took 8 milliseconds Mar 28 20:24:11 raspberry-pi volumio[1037]: info: sendMpdCommand status took 6 milliseconds Mar 28 20:24:11 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:11 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:11 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:11 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus play Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::stPlaybackTimer Mar 28 20:24:11 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:11 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:11 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.760+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=0 volume=50 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.761+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=0 volume=50 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.763+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_STOPPED positionMs=0 volume=50 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.764+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_STOPPED positionMs=0 volume=50 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.766+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=0 volume=50 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.767+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=0 volume=50 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.773+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=0 volume=50 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.774+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=0 volume=50 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.776+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=0 volume=50 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.777+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=0 volume=50 Mar 28 20:24:11 raspberry-pi volumio[1037]: info: ------------------------------ 128ms Mar 28 20:24:11 raspberry-pi volumio[1037]: info: ------------------------------ 122ms Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:11 raspberry-pi volumio[1037]: info: sendMpdCommand status took 157 milliseconds Mar 28 20:24:11 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:11 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:11 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.885+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=50 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.885+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=50 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.888+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=50 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.888+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=50 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.891+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=50 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.891+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=50 Mar 28 20:24:11 raspberry-pi volumio[1037]: info: ------------------------------ 217ms Mar 28 20:24:11 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:11+10:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 28 20:24:11 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:11+10:00" level=trace msg="emitting websocket event: volume" Mar 28 20:24:11 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:11+10:00" level=debug msg="update volume requested to 40632/65535" Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":66,"max":100}} Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 66 Mar 28 20:24:11 raspberry-pi volumio[1037]: info: Setting Volumio Volume from Spotify: 66 Mar 28 20:24:11 raspberry-pi volumio[1037]: info: VolumeController::SetAlsaVolume66 Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 20:24:11 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.976+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:11 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:11.977+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":66,"max":100}} Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 66 Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":66,"max":100}} Mar 28 20:24:11 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 66 Mar 28 20:24:11 raspberry-pi volumio[1037]: info: Mar 28 20:24:11 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:11 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:11 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:11 raspberry-pi volumio[1037]: info: Mar 28 20:24:11 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:11 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:11 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:11 raspberry-pi volumio[1037]: info: Mar 28 20:24:11 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:12 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:12 raspberry-pi volumio[1037]: info: sendMpdCommand status took 5 milliseconds Mar 28 20:24:12 raspberry-pi volumio[1037]: info: sendMpdCommand status took 3 milliseconds Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.079+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.080+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.083+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.083+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.085+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.087+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.089+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.089+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.092+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.094+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.095+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.096+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.127+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.128+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:12 raspberry-pi volumio[1037]: info: ------------------------------ 142ms Mar 28 20:24:12 raspberry-pi volumio[1037]: info: ------------------------------ 140ms Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Mar 28 20:24:12 raspberry-pi volumio[1037]: info: sendMpdCommand status took 186 milliseconds Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.227+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.228+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.230+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.231+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.237+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.238+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=66 Mar 28 20:24:12 raspberry-pi volumio[1037]: info: ------------------------------ 255ms Mar 28 20:24:12 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:12+10:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 28 20:24:12 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:12+10:00" level=trace msg="emitting websocket event: volume" Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":62,"max":100}} Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 62 Mar 28 20:24:12 raspberry-pi volumio[1037]: info: Setting Volumio Volume from Spotify: 62 Mar 28 20:24:12 raspberry-pi volumio[1037]: info: VolumeController::SetAlsaVolume62 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.308+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.311+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.338+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.339+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":62,"max":100}} Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 62 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":62,"max":100}} Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 62 Mar 28 20:24:12 raspberry-pi volumio[1037]: info: Mar 28 20:24:12 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:12 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:12 raspberry-pi volumio[1037]: info: Mar 28 20:24:12 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:12 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:12 raspberry-pi volumio[1037]: info: Mar 28 20:24:12 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:12 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:12 raspberry-pi volumio[1037]: info: sendMpdCommand status took 5 milliseconds Mar 28 20:24:12 raspberry-pi volumio[1037]: info: sendMpdCommand status took 4 milliseconds Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.426+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.427+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.428+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.429+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.431+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.434+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.436+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.436+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.437+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.438+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.441+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.443+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio[1037]: info: ------------------------------ 114ms Mar 28 20:24:12 raspberry-pi volumio[1037]: info: ------------------------------ 113ms Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 62 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 62 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 62 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 62 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 62 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 62 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 62 Mar 28 20:24:12 raspberry-pi volumio[1037]: info: sendMpdCommand status took 172 milliseconds Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:12 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:12 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.580+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.582+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.583+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.584+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.587+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.588+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=1000 volume=62 Mar 28 20:24:12 raspberry-pi volumio[1037]: info: ------------------------------ 240ms Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 62 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 62 Mar 28 20:24:12 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 62 Mar 28 20:24:12 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:12+10:00" level=debug msg="update volume requested to 38010/65535" Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.887+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:12 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:12.887+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:13 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:13+10:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 28 20:24:13 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:13+10:00" level=trace msg="emitting websocket event: volume" Mar 28 20:24:13 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":58,"max":100}} Mar 28 20:24:13 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 58 Mar 28 20:24:13 raspberry-pi volumio[1037]: info: Setting Volumio Volume from Spotify: 58 Mar 28 20:24:13 raspberry-pi volumio[1037]: info: VolumeController::SetAlsaVolume58 Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.155+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.156+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":58,"max":100}} Mar 28 20:24:13 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 58 Mar 28 20:24:13 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":58,"max":100}} Mar 28 20:24:13 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 58 Mar 28 20:24:13 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Mar 28 20:24:13 raspberry-pi volumio[1037]: info: Mar 28 20:24:13 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:13 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:13 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:13 raspberry-pi volumio[1037]: info: Mar 28 20:24:13 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:13 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:13 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:13 raspberry-pi volumio[1037]: info: Mar 28 20:24:13 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:13 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:13 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:13 raspberry-pi volumio[1037]: info: sendMpdCommand status took 5 milliseconds Mar 28 20:24:13 raspberry-pi volumio[1037]: info: sendMpdCommand status took 3 milliseconds Mar 28 20:24:13 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:13 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:13 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:13 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:13 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:13 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.236+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.237+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.239+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.241+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.242+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.243+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.244+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.245+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.247+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.248+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.251+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.252+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio[1037]: info: ------------------------------ 108ms Mar 28 20:24:13 raspberry-pi volumio[1037]: info: ------------------------------ 106ms Mar 28 20:24:13 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Mar 28 20:24:13 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Mar 28 20:24:13 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Mar 28 20:24:13 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Mar 28 20:24:13 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Mar 28 20:24:13 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Mar 28 20:24:13 raspberry-pi volumio[1037]: info: sendMpdCommand status took 146 milliseconds Mar 28 20:24:13 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:13 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:13 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:13 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.356+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.358+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.359+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.359+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.366+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.368+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=2000 volume=58 Mar 28 20:24:13 raspberry-pi volumio[1037]: info: ------------------------------ 206ms Mar 28 20:24:13 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Mar 28 20:24:13 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Mar 28 20:24:13 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.607+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.609+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.787+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id= title= Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.787+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id= title= Mar 28 20:24:13 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:13+10:00" level=debug msg="update volume requested to 35389/65535" Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.878+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:13 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:13.881+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.148+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.150+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:14 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:14+10:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 28 20:24:14 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:14+10:00" level=trace msg="emitting websocket event: volume" Mar 28 20:24:14 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":54,"max":100}} Mar 28 20:24:14 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 54 Mar 28 20:24:14 raspberry-pi volumio[1037]: info: Setting Volumio Volume from Spotify: 54 Mar 28 20:24:14 raspberry-pi volumio[1037]: info: VolumeController::SetAlsaVolume54 Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.233+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.235+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":54,"max":100}} Mar 28 20:24:14 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 54 Mar 28 20:24:14 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":54,"max":100}} Mar 28 20:24:14 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 54 Mar 28 20:24:14 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Mar 28 20:24:14 raspberry-pi volumio[1037]: info: Mar 28 20:24:14 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:14 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:14 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:14 raspberry-pi volumio[1037]: info: Mar 28 20:24:14 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:14 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:14 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:14 raspberry-pi volumio[1037]: info: Mar 28 20:24:14 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:14 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:14 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:14 raspberry-pi volumio[1037]: info: sendMpdCommand status took 5 milliseconds Mar 28 20:24:14 raspberry-pi volumio[1037]: info: sendMpdCommand status took 3 milliseconds Mar 28 20:24:14 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:14 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:14 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:14 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:14 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:14 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.327+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.328+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.338+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.339+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.340+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.342+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.343+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.344+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.347+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.349+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.349+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.350+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.351+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.352+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio[1037]: info: ------------------------------ 132ms Mar 28 20:24:14 raspberry-pi volumio[1037]: info: ------------------------------ 131ms Mar 28 20:24:14 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Mar 28 20:24:14 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Mar 28 20:24:14 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Mar 28 20:24:14 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Mar 28 20:24:14 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Mar 28 20:24:14 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Mar 28 20:24:14 raspberry-pi volumio[1037]: info: sendMpdCommand status took 167 milliseconds Mar 28 20:24:14 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:14 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:14 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:14 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.462+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.464+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.465+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.466+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.468+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.469+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=3000 volume=54 Mar 28 20:24:14 raspberry-pi volumio[1037]: info: ------------------------------ 228ms Mar 28 20:24:14 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Mar 28 20:24:14 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Mar 28 20:24:14 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.507+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.508+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.687+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.687+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.866+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:14 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:14.867+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.049+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.049+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:15 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:15+10:00" level=debug msg="update volume requested to 32768/65535" Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.227+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.228+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.406+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.408+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:15 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:15+10:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 28 20:24:15 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:15+10:00" level=trace msg="emitting websocket event: volume" Mar 28 20:24:15 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":50,"max":100}} Mar 28 20:24:15 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 50 Mar 28 20:24:15 raspberry-pi volumio[1037]: info: Setting Volumio Volume from Spotify: 50 Mar 28 20:24:15 raspberry-pi volumio[1037]: info: VolumeController::SetAlsaVolume50 Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.493+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.494+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":50,"max":100}} Mar 28 20:24:15 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 50 Mar 28 20:24:15 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":50,"max":100}} Mar 28 20:24:15 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 50 Mar 28 20:24:15 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:15 raspberry-pi volumio[1037]: info: Mar 28 20:24:15 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:15 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:15 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:15 raspberry-pi volumio[1037]: info: Mar 28 20:24:15 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:15 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:15 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:15 raspberry-pi volumio[1037]: info: Mar 28 20:24:15 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:15 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:15 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:15 raspberry-pi volumio[1037]: info: sendMpdCommand status took 5 milliseconds Mar 28 20:24:15 raspberry-pi volumio[1037]: info: sendMpdCommand status took 3 milliseconds Mar 28 20:24:15 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:15 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:15 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:15 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:15 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:15 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.590+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.591+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.599+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.600+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.603+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.603+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.606+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.607+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.610+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.611+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.617+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.618+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.620+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.621+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio[1037]: info: ------------------------------ 134ms Mar 28 20:24:15 raspberry-pi volumio[1037]: info: ------------------------------ 133ms Mar 28 20:24:15 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:15 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:15 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:15 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:15 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:15 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:15 raspberry-pi volumio[1037]: info: sendMpdCommand status took 178 milliseconds Mar 28 20:24:15 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:15 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:15 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:15 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.729+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.731+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.733+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.734+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.737+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.737+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=4000 volume=50 Mar 28 20:24:15 raspberry-pi volumio[1037]: info: ------------------------------ 233ms Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.777+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.782+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:15 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:15 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:15 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.947+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:15 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:15.947+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:16 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:16.126+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:16 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:16.128+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:16 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:16.667+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:16 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:16.669+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:16 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:16.937+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:16 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:16.938+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:17 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:17.116+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:17 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:17.116+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:17 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:17.476+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:17 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:17.476+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:17 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:17.656+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:17 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:17.656+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:17 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:17.836+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:17 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:17.838+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.106+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.106+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.331+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.333+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:18 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:18+10:00" level=debug msg="update volume requested to 30037/65535" Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.646+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.648+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:18 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:18+10:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 28 20:24:18 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:18+10:00" level=trace msg="emitting websocket event: volume" Mar 28 20:24:18 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Mar 28 20:24:18 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Mar 28 20:24:18 raspberry-pi volumio[1037]: info: Setting Volumio Volume from Spotify: 46 Mar 28 20:24:18 raspberry-pi volumio[1037]: info: VolumeController::SetAlsaVolume46 Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.847+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=7000 volume=46 Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.850+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=7000 volume=46 Mar 28 20:24:18 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Mar 28 20:24:18 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Mar 28 20:24:18 raspberry-pi volumio[1037]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Mar 28 20:24:18 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Mar 28 20:24:18 raspberry-pi volumio[1037]: info: Mar 28 20:24:18 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:18 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:18 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:18 raspberry-pi volumio[1037]: info: Mar 28 20:24:18 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:18 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:18 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:18 raspberry-pi volumio[1037]: info: Mar 28 20:24:18 raspberry-pi volumio[1037]: ---------------------------- MPD announces state update: mixer Mar 28 20:24:18 raspberry-pi volumio[1037]: info: ControllerMpd::getState Mar 28 20:24:18 raspberry-pi volumio[1037]: verbose: ControllerMpd::sendMpdCommand status Mar 28 20:24:18 raspberry-pi volumio[1037]: info: sendMpdCommand status took 5 milliseconds Mar 28 20:24:18 raspberry-pi volumio[1037]: info: sendMpdCommand status took 3 milliseconds Mar 28 20:24:18 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:18 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:18 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.874+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.875+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:18 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:18 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:18 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:18 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:18 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:18 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:18 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:18 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.946+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=8000 volume=46 Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.948+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=8000 volume=46 Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.949+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=8000 volume=46 Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.951+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=8000 volume=46 Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.953+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=8000 volume=46 Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.953+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=8000 volume=46 Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.956+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=8000 volume=46 Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.957+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=8000 volume=46 Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.959+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=8000 volume=46 Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.961+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=8000 volume=46 Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.963+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=8000 volume=46 Mar 28 20:24:18 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:18.965+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=8000 volume=46 Mar 28 20:24:19 raspberry-pi volumio[1037]: info: ------------------------------ 140ms Mar 28 20:24:19 raspberry-pi volumio[1037]: info: ------------------------------ 139ms Mar 28 20:24:19 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Mar 28 20:24:19 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Mar 28 20:24:19 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Mar 28 20:24:19 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Mar 28 20:24:19 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Mar 28 20:24:19 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Mar 28 20:24:19 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Mar 28 20:24:19 raspberry-pi volumio[1037]: info: sendMpdCommand status took 187 milliseconds Mar 28 20:24:19 raspberry-pi volumio[1037]: verbose: ControllerMpd::parseState Mar 28 20:24:19 raspberry-pi volumio[1037]: info: ControllerMpd::pushState Mar 28 20:24:19 raspberry-pi volumio[1037]: info: CoreCommandRouter::servicePushState Mar 28 20:24:19 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:19 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:19 raspberry-pi volumio[1037]: info: CorePlayQueue::getTrack 0 Mar 28 20:24:19 raspberry-pi volumio[1037]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 28 20:24:19 raspberry-pi volumio[1037]: verbose: CURRENT POSITION 0 Mar 28 20:24:19 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState stateService stop Mar 28 20:24:19 raspberry-pi volumio[1037]: info: CoreStateMachine::syncState currentStatus stop Mar 28 20:24:19 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:19 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:19 raspberry-pi volumio[1037]: info: No code Mar 28 20:24:19 raspberry-pi volumio[1037]: info: CoreStateMachine::pushState Mar 28 20:24:19 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioPushState Mar 28 20:24:19 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:19.097+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=8000 volume=46 Mar 28 20:24:19 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:19.099+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=8000 volume=46 Mar 28 20:24:19 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:19.102+10:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" state=STATUS_PLAYING positionMs=8000 volume=46 Mar 28 20:24:19 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:19.104+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=8000 volume=46 Mar 28 20:24:19 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:19.105+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=8000 volume=46 Mar 28 20:24:19 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:19.105+10:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" state=STATUS_PLAYING positionMs=8000 volume=46 Mar 28 20:24:19 raspberry-pi volumio[1037]: info: ------------------------------ 250ms Mar 28 20:24:19 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Mar 28 20:24:19 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Mar 28 20:24:19 raspberry-pi volumio[1037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Mar 28 20:24:19 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 20:24:19 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 20:24:19 raspberry-pi volumio[1037]: info: Discovery: Getting this device information Mar 28 20:24:19 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioGetState Mar 28 20:24:19 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 20:24:19 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:19.275+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:19 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:19.277+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:19 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:19.410+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:19 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:19.413+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:19 raspberry-pi volumio[1037]: verbose: New Socket.io Connection to 192.168.5.84:3000 from 192.168.4.32 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 8 Mar 28 20:24:19 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 20:24:19 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 20:24:19 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:19.815+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:19 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:19.816+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:20 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:20.355+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:20 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:20.356+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:20 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:20.537+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:20 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:20.538+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:20 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:20.805+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:20 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:20.806+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:20 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:20.895+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:20 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:20.896+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:21 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:21.120+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:21 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:21.121+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:21 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:21.345+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:21 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:21.346+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:21 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:21.616+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:21 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:21.616+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:22 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:22.020+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:22 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:22.021+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:22 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:22+10:00" level=debug msg="fetched chunk 4/9, size: 524288" uri="spotify:track:782EcmrSvkOJw56D6vbNQk" Mar 28 20:24:22 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:22.155+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:22 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:22.157+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:22 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:22.380+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:22 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:22.381+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:22 raspberry-pi volumio[1037]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 20:24:22 raspberry-pi volumio[1037]: info: touch_display: About to detect HDMI ports... Mar 28 20:24:22 raspberry-pi volumio[1037]: info: touch_display: X server not ready, cannot detect HDMI ports yet. Mar 28 20:24:23 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:23.370+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:23 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:23.371+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:23 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:23.865+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:23 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:23.866+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:24 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:24.090+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:24 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:24.090+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:24 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:24.180+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:24 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:24.180+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:24 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:24.404+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:24 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:24.407+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:24 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:24.720+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:24 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:24.720+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:24 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:24.809+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:24 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:24.810+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:24 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:24.990+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:24 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:24.990+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:25 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:25.215+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:25 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:25.215+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:25 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:25.394+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:25 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:25.395+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:26 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:26.834+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:26 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:26.837+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:27 raspberry-pi volumio[1037]: info: CALLMETHOD: user_interface touch_display saveScreensaverConf [object Object] Mar 28 20:24:27 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: touch_display , saveScreensaverConf Mar 28 20:24:27 raspberry-pi volumio[1037]: info: CoreCommandRouter::volumioGetState Mar 28 20:24:27 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:27.288+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:27 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:27.288+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:27 raspberry-pi volumio[1037]: error: touch_display: Error waking up the screen: Error: Command failed: /usr/bin/xset -display :undefined s reset dpms force on Mar 28 20:24:27 raspberry-pi volumio[1037]: /usr/bin/xset: unable to open display ":undefined" Mar 28 20:24:27 raspberry-pi volumio[1037]: error: touch_display: Error setting screensaver timeout: Error: ENOENT: no such file or directory, stat '/tmp/.X11-unix/Xundefined' Mar 28 20:24:27 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:27.464+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:27 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:27.466+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:27 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:27.689+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:27 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:27.690+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:27 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:27.869+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:27 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:27.870+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:28 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:28.094+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:28 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:28.095+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:28 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:28.274+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:28 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:28+10:00" level=trace msg="sent dealer ping" Mar 28 20:24:28 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:28.278+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:28 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:28.499+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:28 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:28.500+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:28 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:28+10:00" level=trace msg="received dealer pong" Mar 28 20:24:28 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:28.680+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:28 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:28.680+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:28 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 20:24:28 raspberry-pi volumio[1037]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 28 20:24:28 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:28.908+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:28 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:28.908+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:31 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:31.920+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:31 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:31.921+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:32 raspberry-pi volumio[1037]: info: Starting Uninstall of plugin user_interface - touch_display Mar 28 20:24:32 raspberry-pi volumio[1037]: info: Uninstalling plugin touch_display Mar 28 20:24:32 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:32.380+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:32 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:32.381+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:32 raspberry-pi sudo[2685]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/95-touch_display-plugin.conf Mar 28 20:24:32 raspberry-pi sudo[2685]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 20:24:32 raspberry-pi sudo[2685]: pam_unix(sudo:session): session closed for user root Mar 28 20:24:32 raspberry-pi sudo[2687]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start getty@tty1.service Mar 28 20:24:32 raspberry-pi sudo[2687]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 20:24:32 raspberry-pi sudo[2690]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl enable getty@tty1.service Mar 28 20:24:32 raspberry-pi sudo[2690]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 20:24:32 raspberry-pi sudo[2692]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumio-kiosk.service Mar 28 20:24:32 raspberry-pi sudo[2692]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 20:24:32 raspberry-pi volumio[1037]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/95-touch_display-plugin.conf set. Mar 28 20:24:32 raspberry-pi sudo[2692]: pam_unix(sudo:session): session closed for user root Mar 28 20:24:32 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:32.639+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:32 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:32.642+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:32 raspberry-pi volumio[1037]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 28 20:24:32 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:32.729+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:32 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:32.730+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:32 raspberry-pi volumio[1037]: TypeError: Cannot read properties of undefined (reading 'split') Mar 28 20:24:32 raspberry-pi volumio[1037]: at /data/plugins/user_interface/touch_display/index.js:1298:37 Mar 28 20:24:32 raspberry-pi volumio[1037]: at ChildProcess.exithandler (node:child_process:413:7) Mar 28 20:24:32 raspberry-pi volumio[1037]: at ChildProcess.emit (node:events:514:28) Mar 28 20:24:32 raspberry-pi volumio[1037]: at maybeClose (node:internal/child_process:1105:16) Mar 28 20:24:32 raspberry-pi volumio[1037]: at ChildProcess._handle.onexit (node:internal/child_process:305:5) Mar 28 20:24:32 raspberry-pi volumio[1037]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 28 20:24:32 raspberry-pi systemd[1]: Reloading. Mar 28 20:24:32 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:32.965+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:32 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:32.967+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:33 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:33.190+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:33 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:33.191+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:33 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:33.495+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:33 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:33.495+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:33 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:33.899+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:33 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:33.901+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:33 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:33.989+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:33 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:33.989+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:34 raspberry-pi go-librespot[2604]: time="2026-03-28T20:24:34+10:00" level=debug msg="fetched chunk 5/9, size: 524288" uri="spotify:track:782EcmrSvkOJw56D6vbNQk" Mar 28 20:24:34 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:34.082+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.4.32:45516,00:00:00:00:00:00%02 @ 0x19abb90" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:34 raspberry-pi volumio5-onboarding[1541]: time=2026-03-28T20:24:34.083+10:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02 @ 0x18013e0" id=spotify:track:782EcmrSvkOJw56D6vbNQk title="I Run - Ely Oaks Remix" Mar 28 20:24:34 raspberry-pi 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. Mar 28 20:24:34 raspberry-pi 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. Mar 28 20:24:34 raspberry-pi sudo[2690]: pam_unix(sudo:session): session closed for user root Mar 28 20:24:34 raspberry-pi systemd[1]: Created slice system-getty.slice - Slice /system/getty. Mar 28 20:24:34 raspberry-pi systemd[1]: Started getty@tty1.service - Getty on tty1. Mar 28 20:24:34 raspberry-pi sudo[2687]: pam_unix(sudo:session): session closed for user root Mar 28 20:24:35 raspberry-pi sudo[2735]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-28 20:23' Mar 28 20:24:35 raspberry-pi sudo[2735]: 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"