Jun 12 17:52:01 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Jun 12 17:52:01 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Jun 12 17:52:01 volumio volumio[1215]: info: Discovery: Getting this device information
Jun 12 17:52:01 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState
Jun 12 17:52:01 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Jun 12 17:52:18 volumio go-librespot[1524]: time="2025-06-12T17:52:18-07:00" level=trace msg="sent dealer ping"
Jun 12 17:52:18 volumio go-librespot[1524]: time="2025-06-12T17:52:18-07:00" level=trace msg="received dealer pong"
Jun 12 17:52:21 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service...
Jun 12 17:52:21 volumio dbus-daemon[936]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.81' (uid=0 pid=5258 comm="timedatectl show --property=NTPSynchronized --valu")
Jun 12 17:52:21 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service...
Jun 12 17:52:21 volumio dbus-daemon[936]: [system] Successfully activated service 'org.freedesktop.timedate1'
Jun 12 17:52:21 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service.
Jun 12 17:52:21 volumio setdatetime-helper.sh[5257]: Time is not synchronized. Attempting to sync...
Jun 12 17:52:21 volumio sudo[5266]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Fri, 13 Jun 2025 00:52:21 GMT#015'
Jun 12 17:52:21 volumio sudo[5266]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Jun 12 17:52:21 volumio setdatetime-helper.sh[5267]: Thu Jun 12 17:52:21 PDT 2025
Jun 12 17:52:21 volumio setdatetime-helper.sh[5257]: Time synchronized successfully.
Jun 12 17:52:21 volumio sudo[5266]: pam_unix(sudo:session): session closed for user root
Jun 12 17:52:21 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully.
Jun 12 17:52:21 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service.
Jun 12 17:52:21 volumio systemd-journald[425]: Time jumped backwards, rotating.
Jun 12 17:52:31 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Jun 12 17:52:31 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Jun 12 17:52:31 volumio volumio[1215]: info: Discovery: Getting this device information
Jun 12 17:52:31 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState
Jun 12 17:52:31 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Jun 12 17:52:33 volumio systemd[1]: rp1-test.service: Deactivated successfully.
Jun 12 17:52:33 volumio systemd[1]: Stopped rp1-test.service - Check for RP1 displays for Xorg.
Jun 12 17:52:33 volumio systemd[1]: glamor-test.service: Deactivated successfully.
Jun 12 17:52:33 volumio systemd[1]: Stopped glamor-test.service - Check for glamor.
Jun 12 17:52:33 volumio systemd[1]: Reloading.
Jun 12 17:52:34 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Jun 12 17:52:34 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Jun 12 17:52:34 volumio 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.
Jun 12 17:52:34 volumio 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.
Jun 12 17:52:34 volumio systemd[1]: Reloading.
Jun 12 17:52:34 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Jun 12 17:52:34 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Jun 12 17:52:34 volumio 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.
Jun 12 17:52:34 volumio 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.
Jun 12 17:52:44 volumio systemd[1]: Reloading.
Jun 12 17:52:44 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Jun 12 17:52:44 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Jun 12 17:52:44 volumio 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.
Jun 12 17:52:44 volumio 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.
Jun 12 17:52:45 volumio systemd[1]: Reloading.
Jun 12 17:52:45 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Jun 12 17:52:45 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Jun 12 17:52:45 volumio 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.
Jun 12 17:52:45 volumio 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.
Jun 12 17:52:47 volumio go-librespot[1524]: time="2025-06-12T17:52:47-07:00" level=trace msg="received accesspoint ping"
Jun 12 17:52:47 volumio go-librespot[1524]: time="2025-06-12T17:52:47-07:00" level=trace msg="received accesspoint pong ack"
Jun 12 17:52:47 volumio go-librespot[1524]: time="2025-06-12T17:52:47-07:00" level=trace msg="sent dealer ping"
Jun 12 17:52:47 volumio go-librespot[1524]: time="2025-06-12T17:52:47-07:00" level=trace msg="received dealer pong"
Jun 12 17:52:50 volumio systemd[1]: systemd-timedated.service: Deactivated successfully.
Jun 12 17:52:51 volumio systemd[1]: Reloading.
Jun 12 17:52:52 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Jun 12 17:52:52 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Jun 12 17:52:52 volumio 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.
Jun 12 17:52:52 volumio 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.
Jun 12 17:52:52 volumio sudo[4751]: pam_unix(sudo:session): session closed for user root
Jun 12 17:52:52 volumio volumio[1215]: info: Uninstall script completed
Jun 12 17:52:52 volumio volumio[1215]: info: Removing plugin touch_display from configuration
Jun 12 17:52:53 volumio volumio[1215]: info: Successfully removed touch_display configuration files
Jun 12 17:52:53 volumio volumio[1215]: info: Plugin folders cleanup
Jun 12 17:52:53 volumio volumio[1215]: info: Scanning into folder /volumio/app/plugins/
Jun 12 17:52:53 volumio volumio[1215]: info: Scanning category audio_interface
Jun 12 17:52:53 volumio volumio[1215]: info: Scanning category miscellanea
Jun 12 17:52:53 volumio volumio[1215]: info: Scanning category music_service
Jun 12 17:52:53 volumio volumio[1215]: info: Scanning category plugins.json
Jun 12 17:52:53 volumio volumio[1215]: info: Scanning category system_controller
Jun 12 17:52:53 volumio volumio[1215]: info: Scanning category user_interface
Jun 12 17:52:53 volumio volumio[1215]: info: Scanning into folder /data/plugins/
Jun 12 17:52:53 volumio volumio[1215]: info: Scanning category music_service
Jun 12 17:52:53 volumio volumio[1215]: info: Scanning category system_controller
Jun 12 17:52:53 volumio volumio[1215]: info: Scanning category user_interface
Jun 12 17:52:53 volumio volumio[1215]: info: Cleaning folder for touch_display
Jun 12 17:52:53 volumio volumio[1215]: info: Plugin folders cleanup completed
Jun 12 17:52:53 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Jun 12 17:52:53 volumio volumio[1215]: info: [{"prettyName":"Spotify","name":"spop","category":"music_service","version":"4.1.4","icon":"fa-spotify","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"YouTube2","name":"youtube2","category":"music_service","version":"2.3.3","icon":"fa-youtube-play","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"YouTube Music","name":"ytmusic","category":"music_service","version":"2.3.2","icon":"fa-youtube-play","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Sleep Wake Schedule Plugin","name":"SleepWakePlugin","category":"system_controller","version":"2.0.1","icon":"fa-clock-o","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Backup & Restore Data","name":"backup_restore","category":"system_controller","version":"1.7.4","icon":"fa-floppy-o","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"System information","name":"Systeminfo","category":"user_interface","version":"3.0.8","icon":"fa-info-circle","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Peppy-meter-Basic","name":"peppymeterbasic","category":"user_interface","version":"1.0.3","icon":"fa-bar-chart","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Peppy-spectrum","name":"peppyspectrum","category":"user_interface","version":"1.0.35","icon":"fa-bar-chart","isManuallyInstalled":true,"enabled":true,"active":true}]
Jun 12 17:52:53 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken
Jun 12 17:52:58 volumio volumio[1215]: info: Disabling plugin Systeminfo
Jun 12 17:52:58 volumio volumio[1215]: info: Done.
Jun 12 17:53:01 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Jun 12 17:53:01 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Jun 12 17:53:01 volumio volumio[1215]: info: Discovery: Getting this device information
Jun 12 17:53:01 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState
Jun 12 17:53:01 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Jun 12 17:53:01 volumio volumio[1215]: info: Enabling plugin Systeminfo
Jun 12 17:53:01 volumio volumio[1215]: info: Loading plugin "Systeminfo"...
Jun 12 17:53:01 volumio volumio[1215]: info: PLUGIN START: Systeminfo
Jun 12 17:53:01 volumio volumio[1215]: info: Done.
Jun 12 17:53:03 volumio volumio[1215]: info: CoreCommandRouter::getUIConfigOnPlugin
Jun 12 17:53:05 volumio volumio[1215]: info: CALLMETHOD: user_interface Systeminfo getsysteminfo undefined
Jun 12 17:53:05 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: Systeminfo , getsysteminfo
Jun 12 17:53:05 volumio sudo[5871]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/vcgencmd bootloader_version
Jun 12 17:53:05 volumio sudo[5871]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Jun 12 17:53:05 volumio sudo[5871]: pam_unix(sudo:session): session closed for user root
Jun 12 17:53:06 volumio dbus-daemon[936]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.85' (uid=1000 pid=5976 comm="hostnamectl --json short")
Jun 12 17:53:06 volumio systemd[1]: Starting systemd-hostnamed.service - Hostname Service...
Jun 12 17:53:06 volumio dbus-daemon[936]: [system] Successfully activated service 'org.freedesktop.hostname1'
Jun 12 17:53:06 volumio systemd[1]: Started systemd-hostnamed.service - Hostname Service.
Jun 12 17:53:06 volumio dbus-daemon[936]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service' requested by ':1.86' (uid=0 pid=5978 comm="/lib/systemd/systemd-hostnamed")
Jun 12 17:53:06 volumio systemd[1]: Starting polkit.service - Authorization Manager...
Jun 12 17:53:06 volumio polkitd[5980]: Started polkitd version 122
Jun 12 17:53:06 volumio polkitd[5980]: Loading rules from directory /etc/polkit-1/rules.d
Jun 12 17:53:06 volumio polkitd[5980]: Loading rules from directory /usr/share/polkit-1/rules.d
Jun 12 17:53:06 volumio polkitd[5980]: Finished loading, compiling and executing 2 rules
Jun 12 17:53:06 volumio dbus-daemon[936]: [system] Successfully activated service 'org.freedesktop.PolicyKit1'
Jun 12 17:53:06 volumio systemd[1]: Started polkit.service - Authorization Manager.
Jun 12 17:53:06 volumio polkitd[5980]: Acquired the name org.freedesktop.PolicyKit1 on the system bus
Jun 12 17:53:06 volumio dbus-daemon[936]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.86" (uid=0 pid=5978 comm="/lib/systemd/systemd-hostnamed") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.InteractiveAuthorizationRequired" requested_reply="0" destination=":1.85" (uid=1000 pid=5976 comm="hostnamectl --json short")
Jun 12 17:53:07 volumio volumio[1215]: info: board is Raspberry Pi 5 Model B Rev 1.1
Jun 12 17:53:07 volumio volumio[1215]: Storage info 107763M 1158M 100861M
Jun 12 17:53:07 volumio volumio[1215]: Storage info 107763M 1158M 100861M
Jun 12 17:53:07 volumio volumio[1215]: BBBBBBBBBBBBBB-CPU Temp 55 °C
Jun 12 17:53:07 volumio volumio[1215]: info: Firmware detected: 2025/05/08 15:13:17 version 69471177ba7e4cb7597cb2496f2a0b23f19c1113 (release)
Jun 12 17:53:07 volumio volumio[1215]: AAAAAAAAAAAAAAAAAAAAAAAAAA-> 2 <-AAAAAAAAAAAAA
Jun 12 17:53:07 volumio volumio[1215]: AAAAAAAAAAAAAAAAAAAAAAAAAA-> 44100 48000 96000 <-AAAAAAAAAAAAA
Jun 12 17:53:09 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Jun 12 17:53:17 volumio go-librespot[1524]: time="2025-06-12T17:53:17-07:00" level=trace msg="sent dealer ping"
Jun 12 17:53:17 volumio go-librespot[1524]: time="2025-06-12T17:53:17-07:00" level=trace msg="received dealer pong"
Jun 12 17:53:29 volumio volumio[1215]: info: CoreCommandRouter::Close All Modals sent
Jun 12 17:53:31 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Jun 12 17:53:31 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Jun 12 17:53:31 volumio volumio[1215]: info: Discovery: Getting this device information
Jun 12 17:53:31 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState
Jun 12 17:53:31 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Jun 12 17:53:36 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service...
Jun 12 17:53:36 volumio systemd[1]: systemd-hostnamed.service: Deactivated successfully.
Jun 12 17:53:36 volumio dbus-daemon[936]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.88' (uid=0 pid=6652 comm="timedatectl show --property=NTPSynchronized --valu")
Jun 12 17:53:36 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service...
Jun 12 17:53:36 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri
Jun 12 17:53:36 volumio volumio[1215]: info: In handleBrowseUri, curUri=spotify
Jun 12 17:53:36 volumio volumio[1215]: info: Preload queue cleared
Jun 12 17:53:36 volumio volumio[1215]: info: Preload queue cleared
Jun 12 17:53:36 volumio volumio[1215]: info: Preload queue cleared
Jun 12 17:53:36 volumio volumio[1215]: info: Preload queue cleared
Jun 12 17:53:36 volumio dbus-daemon[936]: [system] Successfully activated service 'org.freedesktop.timedate1'
Jun 12 17:53:36 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service.
Jun 12 17:53:36 volumio setdatetime-helper.sh[6649]: Time is not synchronized. Attempting to sync...
Jun 12 17:53:36 volumio sudo[6661]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Fri, 13 Jun 2025 00:53:37 GMT#015'
Jun 12 17:53:36 volumio sudo[6661]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Jun 12 17:53:37 volumio setdatetime-helper.sh[6662]: Thu Jun 12 17:53:37 PDT 2025
Jun 12 17:53:37 volumio sudo[6661]: pam_unix(sudo:session): session closed for user root
Jun 12 17:53:37 volumio setdatetime-helper.sh[6649]: Time synchronized successfully.
Jun 12 17:53:37 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully.
Jun 12 17:53:37 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service.
Jun 12 17:53:38 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri
Jun 12 17:53:38 volumio volumio[1215]: info: In handleBrowseUri, curUri=spotify:playlist:37i9dQZF1DXcBWIGoYBM5M
Jun 12 17:53:40 volumio volumio[1215]: info: Preload queue cleared
Jun 12 17:53:41 volumio volumio[1215]: info: Preload queue cleared
Jun 12 17:53:41 volumio volumio[1215]: info: CoreCommandRouter::volumioReplaceandPlayItems
Jun 12 17:53:41 volumio volumio[1215]: info: CoreStateMachine::ClearQueue
Jun 12 17:53:41 volumio volumio[1215]: info: CoreStateMachine::stop
Jun 12 17:53:41 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined
Jun 12 17:53:41 volumio volumio[1215]: info: CoreStateMachine::updateTrackBlock
Jun 12 17:53:41 volumio volumio[1215]: info: CorePlayQueue::getTrackBlock
Jun 12 17:53:41 volumio volumio[1215]: info: CoreStateMachine::stPlaybackTimer
Jun 12 17:53:41 volumio volumio[1215]: info: CoreStateMachine::pushState
Jun 12 17:53:41 volumio volumio[1215]: info: CorePlayQueue::getTrack 0
Jun 12 17:53:41 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jun 12 17:53:41 volumio volumio[1215]: info: CoreCommandRouter::volumioPushState
Jun 12 17:53:41 volumio volumio[1215]: info: MRS: Pushing multiroomSync output update for this device
Jun 12 17:53:41 volumio volumio[1215]: info: MRS: Pushing multiroomSync output
Jun 12 17:53:41 volumio volumio[1215]: error: Help! Some callbacks for volumioPushState are crashing!
Jun 12 17:53:41 volumio volumio[1215]: error: Cannot read properties of undefined (reading 'sendVolumeMute')
Jun 12 17:53:41 volumio volumio[1215]: info: CoreStateMachine::serviceStop
Jun 12 17:53:41 volumio volumio[1215]: info: CorePlayQueue::getTrack 0
Jun 12 17:53:41 volumio volumio[1215]: info: CoreCommandRouter::serviceStop
Jun 12 17:53:41 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService mpd
Jun 12 17:53:41 volumio volumio[1215]: info: ControllerMpd::stop
Jun 12 17:53:41 volumio volumio[1215]: verbose: ControllerMpd::sendMpdCommand stop
Jun 12 17:53:41 volumio volumio[1215]: info: CorePlayQueue::clearPlayQueue
Jun 12 17:53:41 volumio volumio[1215]: info: CorePlayQueue::saveQueue
Jun 12 17:53:41 volumio volumio[1215]: info: CoreCommandRouter::volumioPushQueue
Jun 12 17:53:41 volumio volumio[1215]: info: CoreStateMachine::addQueueItems
Jun 12 17:53:41 volumio volumio[1215]: info: CorePlayQueue::addQueueItems
Jun 12 17:53:41 volumio volumio[1215]: info: Preload queue cleared
Jun 12 17:53:41 volumio volumio[1215]: info: Adding Item to queue: spotify:user:spotify:playlist:37i9dQZF1DXcBWIGoYBM5M
Jun 12 17:53:41 volumio volumio[1215]: info: Exploding uri spotify:user:spotify:playlist:37i9dQZF1DXcBWIGoYBM5M in service spop
Jun 12 17:53:41 volumio volumio[1215]: SPOTIFY: EXPLODING URI:spotify:user:spotify:playlist:37i9dQZF1DXcBWIGoYBM5M
Jun 12 17:53:41 volumio volumio[1215]: info: PeppyMeterBasic ---peppymeterbasic status stop
Jun 12 17:53:41 volumio volumio[1215]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Jun 12 17:53:41 volumio volumio[1215]: info: sendMpdCommand stop took 31 milliseconds
Jun 12 17:53:41 volumio sudo[6679]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service
Jun 12 17:53:41 volumio sudo[6679]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Jun 12 17:53:41 volumio volumio[1215]: info: PeppySpectrum ---peppyspectrum status stop
Jun 12 17:53:41 volumio systemd[1]: Stopping peppymeterbasic.service - peppymeterbasic Daemon...
Jun 12 17:53:41 volumio sudo[6682]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service
Jun 12 17:53:41 volumio sudo[6682]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Jun 12 17:53:41 volumio volumio[1215]: info: PeppySpectrum ---peppyspectrum status stop
Jun 12 17:53:41 volumio sudo[6685]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service
Jun 12 17:53:41 volumio sudo[6685]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Jun 12 17:53:41 volumio sudo[6682]: pam_unix(sudo:session): session closed for user root
Jun 12 17:53:41 volumio volumio[1215]: info: peppyspectrum Daemon Stop
Jun 12 17:53:41 volumio sudo[6685]: pam_unix(sudo:session): session closed for user root
Jun 12 17:53:41 volumio volumio[1215]: info: peppyspectrum Daemon Stop
Jun 12 17:53:42 volumio systemd[1]: peppymeterbasic.service: Deactivated successfully.
Jun 12 17:53:42 volumio systemd[1]: Stopped peppymeterbasic.service - peppymeterbasic Daemon.
Jun 12 17:53:42 volumio systemd[1]: peppymeterbasic.service: Consumed 5min 22.795s CPU time.
Jun 12 17:53:42 volumio sudo[6679]: pam_unix(sudo:session): session closed for user root
Jun 12 17:53:42 volumio volumio[1215]: info: peppymeterbasic Daemon Stop
Jun 12 17:53:42 volumio volumio[1215]: info: CoreCommandRouter::volumioPushQueue
Jun 12 17:53:42 volumio volumio[1215]: info: CorePlayQueue::saveQueue
Jun 12 17:53:42 volumio volumio[1215]: info: CoreStateMachine::updateTrackBlock
Jun 12 17:53:42 volumio volumio[1215]: info: CorePlayQueue::getTrackBlock
Jun 12 17:53:42 volumio volumio[1215]: info: CoreCommandRouter::volumioPlay
Jun 12 17:53:42 volumio volumio[1215]: info: CoreStateMachine::play index 0
Jun 12 17:53:42 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined
Jun 12 17:53:42 volumio volumio[1215]: info: CoreStateMachine::stop
Jun 12 17:53:42 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined
Jun 12 17:53:42 volumio volumio[1215]: info: CoreStateMachine::play index undefined
Jun 12 17:53:42 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined
Jun 12 17:53:42 volumio volumio[1215]: info: CorePlayQueue::getTrack 0
Jun 12 17:53:42 volumio volumio[1215]: info: CoreStateMachine::startPlaybackTimer
Jun 12 17:53:42 volumio volumio[1215]: info: CorePlayQueue::getTrack 0
Jun 12 17:53:42 volumio volumio[1215]: info: [1749776022659] ControllerSpotify::clearAddPlayTrack
Jun 12 17:53:42 volumio volumio[1215]: info: Sending Spotify command with payload to local API: /player/play
Jun 12 17:53:42 volumio go-librespot[1524]: time="2025-06-12T17:53:42-07:00" level=debug msg="resolved context of track" uri="spotify:track:42UBPzRMh5yyz0EDPr6fr1"
Jun 12 17:53:42 volumio go-librespot[1524]: time="2025-06-12T17:53:42-07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:42UBPzRMh5yyz0EDPr6fr1"
Jun 12 17:53:42 volumio go-librespot[1524]: time="2025-06-12T17:53:42-07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:42UBPzRMh5yyz0EDPr6fr1"
Jun 12 17:53:42 volumio go-librespot[1524]: time="2025-06-12T17:53:42-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Jun 12 17:53:42 volumio go-librespot[1524]: time="2025-06-12T17:53:42-07:00" level=trace msg="emitting websocket event: will_play"
Jun 12 17:53:42 volumio volumio[1215]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:42UBPzRMh5yyz0EDPr6fr1","play_origin":"go-librespot"}}
Jun 12 17:53:42 volumio go-librespot[1524]: time="2025-06-12T17:53:42-07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345"
Jun 12 17:53:42 volumio go-librespot[1524]: time="2025-06-12T17:53:42-07:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update
Jun 12 17:53:43 volumio go-librespot[1524]: time="2025-06-12T17:53:43-07:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
Jun 12 17:53:43 volumio go-librespot[1524]: time="2025-06-12T17:53:43-07:00" level=debug msg="selected format OGG_VORBIS_320 (2505e3dbca58affdf192882e91d6f51f16516b1f)" uri="spotify:track:42UBPzRMh5yyz0EDPr6fr1"
Jun 12 17:53:43 volumio go-librespot[1524]: time="2025-06-12T17:53:43-07:00" level=debug msg="requested aes key for file 2505e3dbca58affdf192882e91d6f51f16516b1f, gid: 42UBPzRMh5yyz0EDPr6fr1"
Jun 12 17:53:43 volumio go-librespot[1524]: time="2025-06-12T17:53:43-07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1400"
Jun 12 17:53:43 volumio go-librespot[1524]: time="2025-06-12T17:53:43-07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1144"
Jun 12 17:53:43 volumio go-librespot[1524]: time="2025-06-12T17:53:43-07:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
Jun 12 17:53:43 volumio go-librespot[1524]: time="2025-06-12T17:53:43-07:00" level=debug msg="fetched first chunk of 18, total size is 9277491 bytes" uri="spotify:track:42UBPzRMh5yyz0EDPr6fr1"
Jun 12 17:53:43 volumio go-librespot[1524]: time="2025-06-12T17:53:43-07:00" level=debug msg="created new output device"
Jun 12 17:53:43 volumio go-librespot[1524]: time="2025-06-12T17:53:43-07: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"
Jun 12 17:53:43 volumio go-librespot[1524]: time="2025-06-12T17:53:43-07:00" level=info msg="loaded track \"Manchild\" (paused: false, position: 0ms, duration: 213645ms, prefetched: false)" uri="spotify:track:42UBPzRMh5yyz0EDPr6fr1"
Jun 12 17:53:43 volumio go-librespot[1524]: time="2025-06-12T17:53:43-07:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:42UBPzRMh5yyz0EDPr6fr1"
Jun 12 17:53:43 volumio go-librespot[1524]: time="2025-06-12T17:53:43-07:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:42UBPzRMh5yyz0EDPr6fr1"
Jun 12 17:53:43 volumio go-librespot[1524]: time="2025-06-12T17:53:43-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Jun 12 17:53:43 volumio go-librespot[1524]: time="2025-06-12T17:53:43-07:00" level=trace msg="scheduling prefetch in 184s"
Jun 12 17:53:43 volumio go-librespot[1524]: time="2025-06-12T17:53:43-07:00" level=trace msg="emitting websocket event: metadata"
Jun 12 17:53:43 volumio volumio[1215]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:42UBPzRMh5yyz0EDPr6fr1","name":"Manchild","artist_names":["Sabrina Carpenter"],"album_name":"Manchild","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02062c6573009fdebd43de443b","position":0,"duration":213645,"release_date":"year:2025 month:6 day:5","track_number":1,"disc_number":1}}
Jun 12 17:53:43 volumio go-librespot[1524]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed.
Jun 12 17:53:43 volumio go-librespot[1512]: Aborted
Jun 12 17:53:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a
Jun 12 17:53:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jun 12 17:53:43 volumio volumio[1215]: info: Connection to go-librespot Websocket closed
Jun 12 17:53:46 volumio volumio[1215]: info: Initializing connection to go-librespot Websocket
Jun 12 17:53:46 volumio volumio[1215]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jun 12 17:53:46 volumio volumio[1215]: info: Preload queue cleared
Jun 12 17:53:46 volumio volumio[1215]: info: CoreCommandRouter::volumioReplaceandPlayItems
Jun 12 17:53:46 volumio volumio[1215]: info: CoreStateMachine::ClearQueue
Jun 12 17:53:46 volumio volumio[1215]: info: CoreStateMachine::stop
Jun 12 17:53:46 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined
Jun 12 17:53:46 volumio volumio[1215]: info: CorePlayQueue::clearPlayQueue
Jun 12 17:53:46 volumio volumio[1215]: info: CorePlayQueue::saveQueue
Jun 12 17:53:46 volumio volumio[1215]: info: CoreCommandRouter::volumioPushQueue
Jun 12 17:53:46 volumio volumio[1215]: info: CoreStateMachine::addQueueItems
Jun 12 17:53:46 volumio volumio[1215]: info: CorePlayQueue::addQueueItems
Jun 12 17:53:46 volumio volumio[1215]: info: Preload queue cleared
Jun 12 17:53:46 volumio volumio[1215]: info: Adding Item to queue: spotify:user:spotify:playlist:37i9dQZF1DXcBWIGoYBM5M
Jun 12 17:53:46 volumio volumio[1215]: info: Using cached record of: spotify:user:spotify:playlist:37i9dQZF1DXcBWIGoYBM5M
Jun 12 17:53:46 volumio volumio[1215]: info: CoreCommandRouter::volumioPushQueue
Jun 12 17:53:46 volumio volumio[1215]: info: CorePlayQueue::saveQueue
Jun 12 17:53:46 volumio volumio[1215]: info: CoreStateMachine::updateTrackBlock
Jun 12 17:53:46 volumio volumio[1215]: info: CorePlayQueue::getTrackBlock
Jun 12 17:53:46 volumio volumio[1215]: info: CoreCommandRouter::volumioPlay
Jun 12 17:53:46 volumio volumio[1215]: info: CoreStateMachine::play index 0
Jun 12 17:53:46 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined
Jun 12 17:53:46 volumio volumio[1215]: info: CoreStateMachine::stop
Jun 12 17:53:46 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined
Jun 12 17:53:46 volumio volumio[1215]: info: CoreStateMachine::play index undefined
Jun 12 17:53:46 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined
Jun 12 17:53:46 volumio volumio[1215]: info: CorePlayQueue::getTrack 0
Jun 12 17:53:46 volumio volumio[1215]: info: CoreStateMachine::startPlaybackTimer
Jun 12 17:53:46 volumio volumio[1215]: info: CorePlayQueue::getTrack 0
Jun 12 17:53:46 volumio volumio[1215]: info: [1749776026901] ControllerSpotify::clearAddPlayTrack
Jun 12 17:53:46 volumio volumio[1215]: info: Sending Spotify command with payload to local API: /player/play
Jun 12 17:53:46 volumio volumio[1215]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879
Jun 12 17:53:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1.
Jun 12 17:53:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Jun 12 17:53:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Jun 12 17:53:46 volumio go-librespot[6690]: go-librespot daemon starting...
Jun 12 17:53:46 volumio go-librespot[6691]: time="2025-06-12T17:53:46-07:00" level=info msg="running go-librespot 0.2.0"
Jun 12 17:53:46 volumio go-librespot[6691]: time="2025-06-12T17:53:46-07:00" level=debug msg="app state loaded"
Jun 12 17:53:46 volumio go-librespot[6691]: time="2025-06-12T17:53:46-07:00" level=info msg="api server listening on 127.0.0.1:9879"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=info msg="zeroconf server listening on port 40167"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=debug msg="obtained new client token: AACoHPAHUOjyUvBVmq2LPcb95d0bf3jnQFF8NjYhPhJbm8CW8Y5CQi1/EU0I1FcTEdn8UTt5OJQhWsfHGoWHlcHGKTdDSfTyYwmFpOEBjKRZCVpmVivzR/A3CfiXcjy9dr1M5BoxAWpNP3BVbRrGJd1d1GtWQGl/EgXxTnImouflEYyuvPNcdzNdigGXn1iIAPVIbg6kOrgYRCloS3xVSJNsEotbzNxeH+KafPHfh6XI0iNn1OkLalIQhQ=="
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=debug msg="completed keyexchange"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=debug msg="completed challenge"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=info msg="authenticated AP as 22wbf3d2bwtkml5jrta5crf2a"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=info msg="authenticated Login5 as 22wbf3d2bwtkml5jrta5crf2a"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=debug msg="initializing zeroconf session, username: 22wbf3d2bwtkml5jrta5crf2a"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=debug msg="dealer connection opened"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=trace msg="starting accesspoint recv loop"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=trace msg="starting dealer recv loop"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=trace msg="received accesspoint ping"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481"
Jun 12 17:53:47 volumio go-librespot[6691]: time="2025-06-12T17:53:47-07:00" level=debug msg="received connection id: NTcyYmU4ODctZWZlZC00MWJhLTk2NzUtMWY4NzlmODhkYzI5K2RlYWxlcit0Y3A6Ly8wYWNiZDhjNC5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArMjM4MEUzM0FENzRGQTNDRTcxNTg2ODgwRkZCOENFOUZBNDNBMjBCMzU0NkIyQjkzRUMyODI2NTAxODk4NzZEQQ=="
Jun 12 17:53:48 volumio go-librespot[6691]: time="2025-06-12T17:53:48-07:00" level=trace msg="received accesspoint pong ack"
Jun 12 17:53:48 volumio go-librespot[6691]: time="2025-06-12T17:53:48-07:00" level=debug msg="put connect state because NEW_DEVICE"
Jun 12 17:53:49 volumio volumio[1215]: info: CoreCommandRouter::volumioPlay
Jun 12 17:53:49 volumio volumio[1215]: info: CoreStateMachine::play index undefined
Jun 12 17:53:49 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined
Jun 12 17:53:49 volumio volumio[1215]: info: CorePlayQueue::getTrack 0
Jun 12 17:53:49 volumio volumio[1215]: info: CoreStateMachine::startPlaybackTimer
Jun 12 17:53:49 volumio volumio[1215]: info: CorePlayQueue::getTrack 0
Jun 12 17:53:49 volumio volumio[1215]: info: [1749776029461] ControllerSpotify::clearAddPlayTrack
Jun 12 17:53:49 volumio volumio[1215]: info: Sending Spotify command with payload to local API: /player/play
Jun 12 17:53:49 volumio go-librespot[6691]: time="2025-06-12T17:53:49-07:00" level=debug msg="resolved context of track" uri="spotify:track:42UBPzRMh5yyz0EDPr6fr1"
Jun 12 17:53:49 volumio go-librespot[6691]: time="2025-06-12T17:53:49-07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:42UBPzRMh5yyz0EDPr6fr1"
Jun 12 17:53:49 volumio go-librespot[6691]: time="2025-06-12T17:53:49-07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:42UBPzRMh5yyz0EDPr6fr1"
Jun 12 17:53:49 volumio go-librespot[6691]: time="2025-06-12T17:53:49-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Jun 12 17:53:49 volumio go-librespot[6691]: time="2025-06-12T17:53:49-07:00" level=trace msg="emitting websocket event: will_play"
Jun 12 17:53:49 volumio volumio[1215]: info: Initializing connection to go-librespot Websocket
Jun 12 17:53:49 volumio go-librespot[6691]: time="2025-06-12T17:53:49-07:00" level=debug msg="new websocket client"
Jun 12 17:53:49 volumio volumio[1215]: info: Connection to go-librespot Websocket established
Jun 12 17:53:49 volumio go-librespot[6691]: time="2025-06-12T17:53:49-07:00" level=debug msg="selected format OGG_VORBIS_320 (2505e3dbca58affdf192882e91d6f51f16516b1f)" uri="spotify:track:42UBPzRMh5yyz0EDPr6fr1"
Jun 12 17:53:49 volumio go-librespot[6691]: time="2025-06-12T17:53:49-07:00" level=debug msg="requested aes key for file 2505e3dbca58affdf192882e91d6f51f16516b1f, gid: 42UBPzRMh5yyz0EDPr6fr1"
Jun 12 17:53:50 volumio go-librespot[6691]: time="2025-06-12T17:53:50-07:00" level=debug msg="fetched first chunk of 18, total size is 9277491 bytes" uri="spotify:track:42UBPzRMh5yyz0EDPr6fr1"
Jun 12 17:53:50 volumio go-librespot[6691]: time="2025-06-12T17:53:50-07:00" level=debug msg="created new output device"
Jun 12 17:53:50 volumio go-librespot[6691]: time="2025-06-12T17:53:50-07: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"
Jun 12 17:53:50 volumio go-librespot[6691]: time="2025-06-12T17:53:50-07:00" level=info msg="loaded track \"Manchild\" (paused: false, position: 0ms, duration: 213645ms, prefetched: false)" uri="spotify:track:42UBPzRMh5yyz0EDPr6fr1"
Jun 12 17:53:50 volumio go-librespot[6691]: time="2025-06-12T17:53:50-07:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:42UBPzRMh5yyz0EDPr6fr1"
Jun 12 17:53:50 volumio go-librespot[6691]: time="2025-06-12T17:53:50-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Jun 12 17:53:50 volumio go-librespot[6691]: time="2025-06-12T17:53:50-07:00" level=trace msg="scheduling prefetch in 184s"
Jun 12 17:53:50 volumio go-librespot[6691]: time="2025-06-12T17:53:50-07:00" level=trace msg="emitting websocket event: metadata"
Jun 12 17:53:50 volumio volumio[1215]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:42UBPzRMh5yyz0EDPr6fr1","name":"Manchild","artist_names":["Sabrina Carpenter"],"album_name":"Manchild","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02062c6573009fdebd43de443b","position":0,"duration":213645,"release_date":"year:2025 month:6 day:5","track_number":1,"disc_number":1}}
Jun 12 17:53:50 volumio go-librespot[6691]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed.
Jun 12 17:53:50 volumio go-librespot[6690]: Aborted
Jun 12 17:53:50 volumio volumio[1215]: info: Connection to go-librespot Websocket closed
Jun 12 17:53:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a
Jun 12 17:53:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jun 12 17:53:52 volumio volumio[1215]: info: Getting Spotify volume
Jun 12 17:53:52 volumio volumio[1215]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Jun 12 17:53:52 volumio volumio[1215]: Error: connect ECONNREFUSED 127.0.0.1:9879
Jun 12 17:53:52 volumio volumio[1215]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) {
Jun 12 17:53:52 volumio volumio[1215]: errno: -111,
Jun 12 17:53:52 volumio volumio[1215]: code: 'ECONNREFUSED',
Jun 12 17:53:52 volumio volumio[1215]: syscall: 'connect',
Jun 12 17:53:52 volumio volumio[1215]: address: '127.0.0.1',
Jun 12 17:53:52 volumio volumio[1215]: port: 9879,
Jun 12 17:53:52 volumio volumio[1215]: response: undefined
Jun 12 17:53:52 volumio volumio[1215]: }
Jun 12 17:53:52 volumio volumio[1215]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Jun 12 17:53:52 volumio sudo[6728]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-06-12 17:52'
Jun 12 17:53:52 volumio sudo[6728]: 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="4a70cb031e64a8e498efc3e29470650871ff7d54"
VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6"
VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a"
VOLUMIO_BE_VERSION="04c18c158cc4bac70764c3360b25fcce0c69266a"
VOLUMIO_ARCH="arm"
VOLUMIO_VARIANT="volumio"
VOLUMIO_TEST="FALSE"
VOLUMIO_BUILD_DATE="Sat May 31 04:09:10 UTC 2025"
VOLUMIO_VERSION="4.005"
VOLUMIO_HARDWARE="pi"
VOLUMIO_DEVICENAME="Raspberry Pi"
VOLUMIO_HASH="f9bd4447a30d4b2c74b3880e7a50e48b"