Jul 08 19:44:00 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:00 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:00 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:00 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:00 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:00 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:01 rpi5-ws840 go-librespot[2099]: time="2025-07-08T19:44:01+02:00" level=trace msg="sent dealer ping" Jul 08 19:44:01 rpi5-ws840 go-librespot[2099]: time="2025-07-08T19:44:01+02:00" level=trace msg="received dealer pong" Jul 08 19:44:01 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:01 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:01 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:01 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:02 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:02 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:02 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:02 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:02 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:02 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:03 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:03 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:03 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:03 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:04 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:04 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:04 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:04 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:05 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:05 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:05 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:05 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:05 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:05 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:06 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:06 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:06 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:06 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:07 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:07 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:07 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:07 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:07 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:07 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:08 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:08 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:08 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:08 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:09 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:09 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:09 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:09 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:09 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:09 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:10 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:10 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:10 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:10 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:11 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:11 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:11 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:11 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:11 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:11 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:12 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:12 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:12 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:12 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:12 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:12 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:13 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:13 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:13 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:13 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:14 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:14 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:14 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jul 08 19:44:14 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jul 08 19:44:14 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:14 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:14 rpi5-ws840 volumio[1423]: info: Executing endpoint metavolumio Jul 08 19:44:14 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 08 19:44:14 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:14 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:15 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:15 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:15 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:15 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:16 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:16 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:16 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:16 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:16 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:16 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:17 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:17 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:17 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:17 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:18 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:18 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:18 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:18 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:18 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:18 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:19 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:19 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:19 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:19 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:20 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:20 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:20 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 08 19:44:20 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:20 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:20 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 19:44:20 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 19:44:20 rpi5-ws840 volumio[1423]: info: Discovery: Getting this device information Jul 08 19:44:20 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:20 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:20 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 19:44:20 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:20 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:21 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:21 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:21 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:21 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:22 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:22 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:22 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:22 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:22 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:22 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:23 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:23 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:23 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:23 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:24 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:24 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:24 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:24 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:24 rpi5-ws840 volumio[1423]: info: Received OAUTH Data Jul 08 19:44:24 rpi5-ws840 volumio[1423]: info: Executing Spotify Oauth Login Jul 08 19:44:24 rpi5-ws840 volumio[1423]: info: Saving Spotify Refresh Token Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:25 rpi5-ws840 volumio[1423]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 08 19:44:25 rpi5-ws840 volumio[1423]: SPOTIFY: BQCefwVhAj_87sY7_CpVcSw5WFT3EL3T8mWJ8RDv5mfz2xw4XxU3mzrQXs9H2dLVA4oU9v0L-kMRTRjzUUMQirFqADOEdDy9ql-p7NCJQD73TtLfYlz5jr-LBgWIqxjMHxLpx_BYiK0Z66UjV8jt1G4UR7s1wvnEE7ELXDWZPlBPV8AyzTA1WZ5wvqH8NEvQtpOHoKysMcScGmfRkZlF8KmJzLjt7A214Dj8V7bx_-KJeTi7Hqe1eiU2vJkBw1nXTUqN4qYrIXQl_iv5t5rEMrjTYJpPNoMN-Oy5j9Cuzon5Vni-HGF1oAAK81jeAbC9lLbPMvVKOtQ57z4lhzuLM1W-p5chPjZOkjcggZnHglTzVTaxKfk4wrLuAj7o Jul 08 19:44:25 rpi5-ws840 volumio[1423]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: New Spotify access token = BQCefwVhAj_87sY7_CpVcSw5WFT3EL3T8mWJ8RDv5mfz2xw4XxU3mzrQXs9H2dLVA4oU9v0L-kMRTRjzUUMQirFqADOEdDy9ql-p7NCJQD73TtLfYlz5jr-LBgWIqxjMHxLpx_BYiK0Z66UjV8jt1G4UR7s1wvnEE7ELXDWZPlBPV8AyzTA1WZ5wvqH8NEvQtpOHoKysMcScGmfRkZlF8KmJzLjt7A214Dj8V7bx_-KJeTi7Hqe1eiU2vJkBw1nXTUqN4qYrIXQl_iv5t5rEMrjTYJpPNoMN-Oy5j9Cuzon5Vni-HGF1oAAK81jeAbC9lLbPMvVKOtQ57z4lhzuLM1W-p5chPjZOkjcggZnHglTzVTaxKfk4wrLuAj7o Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: Spotify credentials grant success - running version from March 24, 2019 Jul 08 19:44:25 rpi5-ws840 volumio[1423]: SPOTIFY: User informations: {"country":"NL","display_name":"Marco","email":"m.botermans@home.nl","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/z4ujt0w8jsm3yt93kz6hrseoy"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/z4ujt0w8jsm3yt93kz6hrseoy","id":"z4ujt0w8jsm3yt93kz6hrseoy","images":[],"product":"premium","type":"user","uri":"spotify:user:z4ujt0w8jsm3yt93kz6hrseoy"} Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: Creating Spotify config file Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: Spotify config file written Jul 08 19:44:25 rpi5-ws840 sudo[3311]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 08 19:44:25 rpi5-ws840 sudo[3311]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 08 19:44:25 rpi5-ws840 systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Jul 08 19:44:25 rpi5-ws840 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jul 08 19:44:25 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Killing process 2100 (go-librespot) with signal SIGKILL. Jul 08 19:44:25 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jul 08 19:44:25 rpi5-ws840 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 08 19:44:25 rpi5-ws840 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 08 19:44:25 rpi5-ws840 sudo[3311]: pam_unix(sudo:session): session closed for user root Jul 08 19:44:25 rpi5-ws840 dbus-daemon[900]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.38' (uid=0 pid=3314 comm="timedatectl show --property=NTPSynchronized --valu") Jul 08 19:44:25 rpi5-ws840 go-librespot[3317]: go-librespot daemon starting... Jul 08 19:44:25 rpi5-ws840 sudo[3318]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 08 19:44:25 rpi5-ws840 sudo[3318]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=info msg="running go-librespot 0.2.0" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=debug msg="app state loaded" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: Connection to go-librespot Websocket closed Jul 08 19:44:25 rpi5-ws840 sudo[3323]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 08 19:44:25 rpi5-ws840 sudo[3323]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 08 19:44:25 rpi5-ws840 sudo[3318]: pam_unix(sudo:session): session closed for user root Jul 08 19:44:25 rpi5-ws840 systemd[1]: Starting systemd-timedated.service - Time & Date Service... Jul 08 19:44:25 rpi5-ws840 sudo[3323]: pam_unix(sudo:session): session closed for user root Jul 08 19:44:25 rpi5-ws840 volumio[1423]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 08 19:44:25 rpi5-ws840 volumio[1423]: SPOTIFY: BQBz-q0MCFm4pOfwy-22PLO6GzCgh-JgbEGtYNlrIIX9XkEDW4-1gr6FguzURdnHzA8r4qKB7tGUQ3u6bxxTzzM525PmtP084-nTOo4rk0bRNZ7zOKgQeqYjl6wnA8GNZbqCuRmuDa2P4hGXUbB2-Sem7AzUeUCF_hgQB9EtRxl6K08_TPPTDvqSfH-ue6m-_Jspk-17uUJmhofP3YrGId1ectwc49Depx6vZ35_ErNqhixU-VAtulHDoETdiHdgEC1wGx6e42sJSZg6LL0E8e4iXAflvqiSUSzjwExJxYujFWC1iaCpZ40TfXweQrP8s33YER7HbGJZrie06JNzxFIzt0UIHTr5mpaehJA7gg6YLMIEamTTy0wJA0Mz Jul 08 19:44:25 rpi5-ws840 volumio[1423]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: New Spotify access token = BQBz-q0MCFm4pOfwy-22PLO6GzCgh-JgbEGtYNlrIIX9XkEDW4-1gr6FguzURdnHzA8r4qKB7tGUQ3u6bxxTzzM525PmtP084-nTOo4rk0bRNZ7zOKgQeqYjl6wnA8GNZbqCuRmuDa2P4hGXUbB2-Sem7AzUeUCF_hgQB9EtRxl6K08_TPPTDvqSfH-ue6m-_Jspk-17uUJmhofP3YrGId1ectwc49Depx6vZ35_ErNqhixU-VAtulHDoETdiHdgEC1wGx6e42sJSZg6LL0E8e4iXAflvqiSUSzjwExJxYujFWC1iaCpZ40TfXweQrP8s33YER7HbGJZrie06JNzxFIzt0UIHTr5mpaehJA7gg6YLMIEamTTy0wJA0Mz Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: Spotify credentials grant success - running version from March 24, 2019 Jul 08 19:44:25 rpi5-ws840 dbus-daemon[900]: [system] Successfully activated service 'org.freedesktop.timedate1' Jul 08 19:44:25 rpi5-ws840 systemd[1]: Started systemd-timedated.service - Time & Date Service. Jul 08 19:44:25 rpi5-ws840 setdatetime-helper.sh[3313]: Time is not synchronized. Attempting to sync... Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=info msg="zeroconf server listening on port 33563" Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:25 rpi5-ws840 sudo[3336]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Tue, 08 Jul 2025 17:44:25 GMT#015' Jul 08 19:44:25 rpi5-ws840 sudo[3336]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jul 08 19:44:25 rpi5-ws840 volumio[1423]: SPOTIFY: User informations: {"country":"NL","display_name":"Marco","email":"m.botermans@home.nl","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/z4ujt0w8jsm3yt93kz6hrseoy"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/z4ujt0w8jsm3yt93kz6hrseoy","id":"z4ujt0w8jsm3yt93kz6hrseoy","images":[],"product":"premium","type":"user","uri":"spotify:user:z4ujt0w8jsm3yt93kz6hrseoy"} Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: Spotify Successfully logged in Jul 08 19:44:25 rpi5-ws840 setdatetime-helper.sh[3337]: Tue Jul 8 19:44:25 CEST 2025 Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: [1751996665000] CoreMusicLibrary::Adding element Spotify Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 19:44:25 rpi5-ws840 volumio[1423]: Cannot find translation for source 80s80s Radio Jul 08 19:44:25 rpi5-ws840 volumio[1423]: Cannot find translation for source Radio Paradise Jul 08 19:44:25 rpi5-ws840 volumio[1423]: Cannot find translation for source Randomizer Jul 08 19:44:25 rpi5-ws840 volumio[1423]: Cannot find translation for source QOBUZ Jul 08 19:44:25 rpi5-ws840 volumio[1423]: Cannot find translation for source TIDAL Jul 08 19:44:25 rpi5-ws840 volumio[1423]: Cannot find translation for source Spotify Jul 08 19:44:25 rpi5-ws840 systemd-journald[456]: Time jumped backwards, rotating. Jul 08 19:44:25 rpi5-ws840 sudo[3336]: pam_unix(sudo:session): session closed for user root Jul 08 19:44:25 rpi5-ws840 setdatetime-helper.sh[3313]: Time synchronized successfully. Jul 08 19:44:25 rpi5-ws840 systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Jul 08 19:44:25 rpi5-ws840 systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=debug msg="obtained new client token: AAC141prgagOPsmk40krNV4s16w5u8zfws76qh6RE1sFhb1NhoO/0aYNyDMKAimqgYkGkpika1kQbVFuf7/14c7NXDufHVZFzt6amAubR312XxOe7RIZc/2PWZi+HrwVJgx3//WbQIbOhRR5a8VIK+Wd54/GBxSwDwAcKXIhKW4im2p5BmSnRbWSffKIa1zxGi2EcPQxZ1lK5w1J1DRrZukasjPtwJULXR5s2JqLtn/Nvg2DYKocrSI/TUU=" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=debug msg="completed keyexchange" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=debug msg="completed challenge" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=info msg="authenticated AP as z4ujt0w8jsm3yt93kz6hrseoy" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=info msg="authenticated Login5 as z4ujt0w8jsm3yt93kz6hrseoy" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=debug msg="initializing zeroconf session, username: z4ujt0w8jsm3yt93kz6hrseoy" Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=debug msg="dealer connection opened" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=trace msg="starting accesspoint recv loop" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=trace msg="starting dealer recv loop" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=trace msg="received accesspoint ping" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=debug msg="received connection id: ZjAwZmZmNzMtZTg1Ni00ZjE4LTk3MDUtMzE4NDY2Nzc5YzIxK2RlYWxlcit0Y3A6Ly8wYWIxNTEyOS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArNDZENzJFOURGQkQ1NTJGOTk4MzE5NEFBMUQwRjFEMEQ1REFEQzM1RTk2RjU1NzM0Mjg3OTAwQzUxRjA4NUEyMA==" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=trace msg="received accesspoint pong ack" Jul 08 19:44:25 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:25+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:25 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:25 rpi5-ws840 volumio[1423]: verbose: New Socket.io Connection to 192.168.1.215 from 192.168.1.106 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/138.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 15 Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: Received Get System Info Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: Discovery: Getting this device information Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetVisibleSources Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: Received Get System Info Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: Discovery: Getting this device information Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: Listing playlists Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: Received Get System Info Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: Discovery: Getting this device information Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:26 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 19:44:27 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:27 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:27 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:27 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:27 rpi5-ws840 volumio[1423]: info: Initializing connection to go-librespot Websocket Jul 08 19:44:27 rpi5-ws840 volumio[1423]: info: go-librespot daemon successfully initialized Jul 08 19:44:27 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:27+02:00" level=debug msg="new websocket client" Jul 08 19:44:27 rpi5-ws840 volumio[1423]: info: Connection to go-librespot Websocket established Jul 08 19:44:27 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:27 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:28 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jul 08 19:44:28 rpi5-ws840 volumio[1423]: info: Received Get System Info Jul 08 19:44:28 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 19:44:28 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 19:44:28 rpi5-ws840 volumio[1423]: info: Discovery: Getting this device information Jul 08 19:44:28 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:28 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:28 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 19:44:28 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:28 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:28 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:28 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:29 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:29 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:29 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:29 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:29 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:29 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:29 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:29 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:29 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetQueue Jul 08 19:44:29 rpi5-ws840 volumio[1423]: info: CoreStateMachine::getQueue Jul 08 19:44:29 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getQueue Jul 08 19:44:30 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:30 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:30 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:30 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:30 rpi5-ws840 volumio[1423]: info: Initializing connection to go-librespot Websocket Jul 08 19:44:30 rpi5-ws840 volumio[1423]: info: Getting Spotify volume Jul 08 19:44:30 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:30+02:00" level=debug msg="new websocket client" Jul 08 19:44:30 rpi5-ws840 volumio[1423]: info: Connection to go-librespot Websocket established Jul 08 19:44:30 rpi5-ws840 volumio[1423]: info: Spotify volume: 100 Jul 08 19:44:30 rpi5-ws840 volumio[1423]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 16 Jul 08 19:44:30 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:30 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:30 rpi5-ws840 volumio[1423]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 08 19:44:30 rpi5-ws840 volumio[1423]: SPOTIFY: SPOTIFY VOLUME 100 Jul 08 19:44:30 rpi5-ws840 volumio[1423]: SPOTIFY: VOLUMIO VOLUME 46 Jul 08 19:44:30 rpi5-ws840 volumio[1423]: SPOTIFY: DELTA VOLUME ENOUGH: true Jul 08 19:44:30 rpi5-ws840 volumio[1423]: info: Setting Spotify Volume from Volumio: 46 Jul 08 19:44:30 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jul 08 19:44:30 rpi5-ws840 volumio[1423]: info: In handleBrowseUri, curUri=spotify Jul 08 19:44:31 rpi5-ws840 volumio[1423]: info: Preload queue cleared Jul 08 19:44:31 rpi5-ws840 volumio[1423]: info: Preload queue cleared Jul 08 19:44:31 rpi5-ws840 volumio[1423]: info: Preload queue cleared Jul 08 19:44:31 rpi5-ws840 volumio[1423]: info: Preload queue cleared Jul 08 19:44:31 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:31 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:31 rpi5-ws840 volumio[1423]: info: Executing endpoint metavolumio Jul 08 19:44:31 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 08 19:44:31 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:31 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:31 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:31 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:32 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:32 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:32 rpi5-ws840 volumio[1423]: SPOTIFY: SETTING SPOTIFY VOLUME 46 Jul 08 19:44:32 rpi5-ws840 volumio[1423]: info: Sending Spotify command with payload to local API: /player/volume Jul 08 19:44:32 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:32+02:00" level=debug msg="update volume to 30146/65535" Jul 08 19:44:32 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:32 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:33 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:33 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:33 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:33+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jul 08 19:44:33 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:33+02:00" level=trace msg="emitting websocket event: volume" Jul 08 19:44:33 rpi5-ws840 volumio[1423]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Jul 08 19:44:33 rpi5-ws840 volumio[1423]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Jul 08 19:44:33 rpi5-ws840 volumio[1423]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Jul 08 19:44:33 rpi5-ws840 volumio[1423]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Jul 08 19:44:33 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:33 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:33 rpi5-ws840 volumio[1423]: info: Getting Spotify volume Jul 08 19:44:33 rpi5-ws840 volumio[1423]: info: Spotify volume: 46 Jul 08 19:44:33 rpi5-ws840 volumio[1423]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 16 Jul 08 19:44:33 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:33 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:33 rpi5-ws840 volumio[1423]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 08 19:44:33 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:33 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:34 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:34 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:34 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:34 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:35 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:35 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:35 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jul 08 19:44:35 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:35 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:35 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jul 08 19:44:35 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:35 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:36 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:36 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:36 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:36 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:37 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:37 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:37 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:37 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:38 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:38 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:38 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:38 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:38 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:38 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:39 rpi5-ws840 volumio[1423]: Searching plugin music_service/spop Jul 08 19:44:39 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: spop , search Jul 08 19:44:39 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:39 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:39 rpi5-ws840 volumio[1423]: info: All search sources collected, pushing search results Jul 08 19:44:39 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:39 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:40 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:40 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:40 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:40 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:40 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:40 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:41 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:41 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:41 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:41 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:42 rpi5-ws840 volumio[1423]: Searching plugin music_service/spop Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: spop , search Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: Received Get System Version Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: Received Get System Info Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: Discovery: Getting this device information Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:42 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 19:44:43 rpi5-ws840 volumio[1423]: info: All search sources collected, pushing search results Jul 08 19:44:43 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:43 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:43 rpi5-ws840 volumio[1423]: Searching plugin music_service/spop Jul 08 19:44:43 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: spop , search Jul 08 19:44:43 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:43 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:44 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:44 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:44 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:44 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:44 rpi5-ws840 volumio[1423]: info: All search sources collected, pushing search results Jul 08 19:44:44 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:44 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:44 rpi5-ws840 volumio[1423]: Searching plugin music_service/spop Jul 08 19:44:44 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: spop , search Jul 08 19:44:45 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:45 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:45 rpi5-ws840 volumio[1423]: info: All search sources collected, pushing search results Jul 08 19:44:45 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:45 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:46 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:46 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:46 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:46 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:47 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:47 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:47 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:47 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:47 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:47 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:48 rpi5-ws840 volumio[1423]: Searching plugin music_service/spop Jul 08 19:44:48 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: spop , search Jul 08 19:44:48 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:48 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:48 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:48 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:48 rpi5-ws840 volumio[1423]: info: All search sources collected, pushing search results Jul 08 19:44:49 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:49 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:49 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:49 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:49 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jul 08 19:44:49 rpi5-ws840 volumio[1423]: info: In handleBrowseUri, curUri=spotify:artist:3qm84nBOXUEQ2vnTfUTTFC Jul 08 19:44:49 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:49 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:50 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:50 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:50 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:50 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:51 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:51 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:51 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:51 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:51 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:51 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:52 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:52 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:52 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:52 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:53 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:53 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:53 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:53 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:53 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jul 08 19:44:53 rpi5-ws840 volumio[1423]: info: In handleBrowseUri, curUri=spotify:artist:2ye2Wgw4gimLv2eAKyk1NB Jul 08 19:44:53 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:53 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: Discovery: Getting this device information Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: Preload queue cleared Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:3DwQ7AH3xGD9h65ezslm6q Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:6QAsrXPnMSXIbV0yEJHlEX Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:2MuWTIM3b0YEAskbeeFE1i Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:02xhLoVqpGmOqvolgrwM8w Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:3LpHzQU2CZzZJGdUWV79SI Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:5lqyqPU3JkpCbUbLmTVQPW Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:5ltXoDLlI0rFZAmOXbAp5T Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:2R6UrJ8uWbSIiHWmvRQvN8 Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:28WmNsclKsrVmdv3tDmoYU Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:6FUwPb4mGlUDbx42uspXaZ Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: Preload queue cleared Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: Preload queue cleared Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: Executing endpoint getSimilarArtists Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarArtists Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: Executing endpoint metavolumio Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:54 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:54 rpi5-ws840 systemd[1]: systemd-timedated.service: Deactivated successfully. Jul 08 19:44:55 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:55 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:55 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:55+02:00" level=trace msg="sent dealer ping" Jul 08 19:44:55 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:55+02:00" level=trace msg="received dealer pong" Jul 08 19:44:55 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:55 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:55 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:55 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:56 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:56 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:56 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:56 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Preload queue cleared Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioReplaceandPlayItems Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreStateMachine::ClearQueue Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreStateMachine::stop Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CorePlayQueue::clearPlayQueue Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CorePlayQueue::saveQueue Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioPushQueue Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreStateMachine::addQueueItems Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CorePlayQueue::addQueueItems Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Preload queue cleared Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:3DwQ7AH3xGD9h65ezslm6q Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Exploding uri spotify:track:3DwQ7AH3xGD9h65ezslm6q in service spop Jul 08 19:44:57 rpi5-ws840 volumio[1423]: SPOTIFY: EXPLODING URI:spotify:track:3DwQ7AH3xGD9h65ezslm6q Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:6QAsrXPnMSXIbV0yEJHlEX Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Exploding uri spotify:track:6QAsrXPnMSXIbV0yEJHlEX in service spop Jul 08 19:44:57 rpi5-ws840 volumio[1423]: SPOTIFY: EXPLODING URI:spotify:track:6QAsrXPnMSXIbV0yEJHlEX Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 0 Jul 08 19:44:57 rpi5-ws840 volumio[1423]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3DwQ7AH3xGD9h65ezslm6q","service":"spop","name":"Enter Sandman - Remastered 2021","artist":"Metallica","album":"Metallica (Remastered Deluxe Box Set)","type":"song","duration":331,"albumart":"https://i.scdn.co/image/ab67616d0000b273c1a13209dfe146aef3296e34","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:44:57 rpi5-ws840 volumio[1423]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6QAsrXPnMSXIbV0yEJHlEX","service":"spop","name":"Nothing Else Matters - Remastered 2021","artist":"Metallica","album":"Metallica (Remastered Deluxe Box Set)","type":"song","duration":388,"albumart":"https://i.scdn.co/image/ab67616d0000b273c1a13209dfe146aef3296e34","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioPushQueue Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CorePlayQueue::saveQueue Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreStateMachine::updateTrackBlock Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrackBlock Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioPlay Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreStateMachine::play index 1 Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreStateMachine::addQueueItems Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CorePlayQueue::addQueueItems Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Preload queue cleared Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:2MuWTIM3b0YEAskbeeFE1i Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Exploding uri spotify:track:2MuWTIM3b0YEAskbeeFE1i in service spop Jul 08 19:44:57 rpi5-ws840 volumio[1423]: SPOTIFY: EXPLODING URI:spotify:track:2MuWTIM3b0YEAskbeeFE1i Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:02xhLoVqpGmOqvolgrwM8w Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Exploding uri spotify:track:02xhLoVqpGmOqvolgrwM8w in service spop Jul 08 19:44:57 rpi5-ws840 volumio[1423]: SPOTIFY: EXPLODING URI:spotify:track:02xhLoVqpGmOqvolgrwM8w Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:3LpHzQU2CZzZJGdUWV79SI Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Exploding uri spotify:track:3LpHzQU2CZzZJGdUWV79SI in service spop Jul 08 19:44:57 rpi5-ws840 volumio[1423]: SPOTIFY: EXPLODING URI:spotify:track:3LpHzQU2CZzZJGdUWV79SI Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:5lqyqPU3JkpCbUbLmTVQPW Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Exploding uri spotify:track:5lqyqPU3JkpCbUbLmTVQPW in service spop Jul 08 19:44:57 rpi5-ws840 volumio[1423]: SPOTIFY: EXPLODING URI:spotify:track:5lqyqPU3JkpCbUbLmTVQPW Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:5ltXoDLlI0rFZAmOXbAp5T Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Exploding uri spotify:track:5ltXoDLlI0rFZAmOXbAp5T in service spop Jul 08 19:44:57 rpi5-ws840 volumio[1423]: SPOTIFY: EXPLODING URI:spotify:track:5ltXoDLlI0rFZAmOXbAp5T Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:2R6UrJ8uWbSIiHWmvRQvN8 Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Exploding uri spotify:track:2R6UrJ8uWbSIiHWmvRQvN8 in service spop Jul 08 19:44:57 rpi5-ws840 volumio[1423]: SPOTIFY: EXPLODING URI:spotify:track:2R6UrJ8uWbSIiHWmvRQvN8 Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:28WmNsclKsrVmdv3tDmoYU Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Exploding uri spotify:track:28WmNsclKsrVmdv3tDmoYU in service spop Jul 08 19:44:57 rpi5-ws840 volumio[1423]: SPOTIFY: EXPLODING URI:spotify:track:28WmNsclKsrVmdv3tDmoYU Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:6FUwPb4mGlUDbx42uspXaZ Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Exploding uri spotify:track:6FUwPb4mGlUDbx42uspXaZ in service spop Jul 08 19:44:57 rpi5-ws840 volumio[1423]: SPOTIFY: EXPLODING URI:spotify:track:6FUwPb4mGlUDbx42uspXaZ Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreStateMachine::stop Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreStateMachine::play index undefined Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreStateMachine::startPlaybackTimer Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetVisibleSources Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: [1751996697906] ControllerSpotify::clearAddPlayTrack Jul 08 19:44:57 rpi5-ws840 volumio[1423]: info: Sending Spotify command with payload to local API: /player/play Jul 08 19:44:57 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:57+02:00" level=debug msg="resolved context of track" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:44:57 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:57+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:44:57 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:57+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:44:58 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:58 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:44:58 rpi5-ws840 volumio[1423]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2MuWTIM3b0YEAskbeeFE1i","service":"spop","name":"Master Of Puppets","artist":"Metallica","album":"Master Of Puppets (Remastered)","type":"song","duration":515,"albumart":"https://i.scdn.co/image/ab67616d0000b273668e3aca3167e6e569a9aa20","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:44:58 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:58+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 19:44:58 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:58+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 19:44:58 rpi5-ws840 volumio[1423]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6QAsrXPnMSXIbV0yEJHlEX","play_origin":"go-librespot"}} Jul 08 19:44:58 rpi5-ws840 volumio[1423]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6QAsrXPnMSXIbV0yEJHlEX","play_origin":"go-librespot"}} Jul 08 19:44:58 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:58+02:00" level=debug msg="selected format OGG_VORBIS_320 (004b8a787e861e2a2df69a327ec9bfaae911c167)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:44:58 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:58+02:00" level=debug msg="requested aes key for file 004b8a787e861e2a2df69a327ec9bfaae911c167, gid: 6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:44:58 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:58+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jul 08 19:44:58 rpi5-ws840 volumio[1423]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:02xhLoVqpGmOqvolgrwM8w","service":"spop","name":"One","artist":"Metallica","album":"…And Justice for All (Remastered)","type":"song","duration":446,"albumart":"https://i.scdn.co/image/ab67616d0000b273fe896727e3db1027ed72d885","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:44:58 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:58+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Jul 08 19:44:58 rpi5-ws840 volumio[1423]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3LpHzQU2CZzZJGdUWV79SI","service":"spop","name":"For Whom The Bell Tolls - Remastered","artist":"Metallica","album":"Ride The Lightning (Deluxe / Remastered)","type":"song","duration":309,"albumart":"https://i.scdn.co/image/ab67616d0000b27396a926d07aea417327ea024a","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:44:58 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:58+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jul 08 19:44:58 rpi5-ws840 volumio[1423]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5lqyqPU3JkpCbUbLmTVQPW","service":"spop","name":"The Unforgiven - Remastered 2021","artist":"Metallica","album":"Metallica (Remastered 2021)","type":"song","duration":387,"albumart":"https://i.scdn.co/image/ab67616d0000b27376c60d2128c8e4649b85f2b2","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:44:58 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:58+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1363" Jul 08 19:44:58 rpi5-ws840 volumio[1423]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5ltXoDLlI0rFZAmOXbAp5T","service":"spop","name":"Sad But True - Remastered 2021","artist":"Metallica","album":"Metallica (Remastered Deluxe Box Set)","type":"song","duration":324,"albumart":"https://i.scdn.co/image/ab67616d0000b273c1a13209dfe146aef3296e34","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:44:58 rpi5-ws840 volumio[1423]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2R6UrJ8uWbSIiHWmvRQvN8","service":"spop","name":"Whiskey In The Jar","artist":"Metallica","album":"Garage Inc.","type":"song","duration":304,"albumart":"https://i.scdn.co/image/ab67616d0000b27375e6375e11550746705a9645","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:44:58 rpi5-ws840 volumio[1423]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:28WmNsclKsrVmdv3tDmoYU","service":"spop","name":"Seek & Destroy - Remastered","artist":"Metallica","album":"Kill 'Em All (Remastered)","type":"song","duration":414,"albumart":"https://i.scdn.co/image/ab67616d0000b273d30fcf6340831edbafb45e38","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:44:58 rpi5-ws840 volumio[1423]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6FUwPb4mGlUDbx42uspXaZ","service":"spop","name":"Fuel","artist":"Metallica","album":"Reload","type":"song","duration":269,"albumart":"https://i.scdn.co/image/ab67616d0000b27306cb74d39d123ebe1b3c6631","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:44:58 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioPushQueue Jul 08 19:44:58 rpi5-ws840 volumio[1423]: info: CorePlayQueue::saveQueue Jul 08 19:44:58 rpi5-ws840 volumio[1423]: info: CoreStateMachine::updateTrackBlock Jul 08 19:44:58 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrackBlock Jul 08 19:44:58 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:58+02:00" level=debug msg="fetched first chunk of 28, total size is 14354512 bytes" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:44:58 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:58+02:00" level=debug msg="created new output device" Jul 08 19:44:58 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:58 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:44:58 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:58+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Jul 08 19:44:58 rpi5-ws840 go-librespot[3320]: time="2025-07-08T19:44:58+02:00" level=info msg="loaded track \"Nothing Else Matters - Remastered 2021\" (paused: false, position: 0ms, duration: 388733ms, prefetched: false)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:44:58 rpi5-ws840 go-librespot[3320]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Jul 08 19:44:58 rpi5-ws840 volumio[1423]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jul 08 19:44:58 rpi5-ws840 go-librespot[3317]: Aborted Jul 08 19:44:58 rpi5-ws840 volumio[1423]: info: Connection to go-librespot Websocket closed Jul 08 19:44:58 rpi5-ws840 volumio[1423]: info: Connection to go-librespot Websocket closed Jul 08 19:44:58 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Jul 08 19:44:58 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 08 19:44:58 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:58 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: Preload queue cleared Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:7snQQk1zcKl8gZ92AnueZW Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:0G21yYKMZoHa30cYVi1iA8 Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:6eN1f9KNmiWEhpE2RhQqB5 Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:3YRCqOhFifThpSRFJ1VWFM Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:4JiEyzf0Md7KEFFGWDDdCr Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:2N2yrmodOnVF10mKvItC9P Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:1OEoNpiyqBghuEUaT6Je6U Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:0rFWuqFgHAfuzE8uSB9TWR Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:0dlTGl67UFWcKupzkxZYOn Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: Preloading song: spotify:track:6i4Qi1mJxXjqNIL9HfJhRs Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: Preload queue cleared Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: Preload queue cleared Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: Executing endpoint getSimilarArtists Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarArtists Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: Executing endpoint metavolumio Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:44:59 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:00 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:00 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:00 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:00 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:00 rpi5-ws840 volumio[1423]: verbose: New Socket.io Connection to 192.168.1.215:3000 from 192.168.1.171 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 15 Jul 08 19:45:00 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:00 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:01 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:01 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:01 rpi5-ws840 volumio[1423]: info: Initializing connection to go-librespot Websocket Jul 08 19:45:01 rpi5-ws840 volumio[1423]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 08 19:45:01 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jul 08 19:45:01 rpi5-ws840 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 08 19:45:01 rpi5-ws840 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 08 19:45:01 rpi5-ws840 go-librespot[3390]: go-librespot daemon starting... Jul 08 19:45:01 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:01 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:01 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:01+02:00" level=info msg="running go-librespot 0.2.0" Jul 08 19:45:01 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:01+02:00" level=debug msg="app state loaded" Jul 08 19:45:01 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:01+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 08 19:45:01 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:01+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 08 19:45:01 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:01+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jul 08 19:45:01 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:01+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jul 08 19:45:01 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:01+02:00" level=info msg="zeroconf server listening on port 35155" Jul 08 19:45:01 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:01+02:00" level=debug msg="obtained new client token: AADi6upTRb6GQn9uVHfA2/wIJq4UGnqCrUBotYwF88gju/DI06LRYYIORokUJclvxAKJzG7ONkfb5CKg3lE+8j2oUJDb5c+w1t6YOD9MkNsYrK9CAG/fQxduPLhvSiSliuo2suMqz13/N9JRzn7qUPV+AyoxL9akj8dc0JpzXubC4IMD3/pV0Wl6gsSEdyuW75k7pV8naUAiiD0FnaCRsosA+HKXRXBv7/Jowxw+cWHVtwiLRHp/1kDkiOE=" Jul 08 19:45:02 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:02+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 08 19:45:02 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:02+02:00" level=debug msg="completed keyexchange" Jul 08 19:45:02 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:02+02:00" level=debug msg="completed challenge" Jul 08 19:45:02 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:02+02:00" level=info msg="authenticated AP as z4ujt0w8jsm3yt93kz6hrseoy" Jul 08 19:45:02 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:02 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:02 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:02+02:00" level=info msg="authenticated Login5 as z4ujt0w8jsm3yt93kz6hrseoy" Jul 08 19:45:02 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:02+02:00" level=debug msg="initializing zeroconf session, username: z4ujt0w8jsm3yt93kz6hrseoy" Jul 08 19:45:02 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:02+02:00" level=debug msg="dealer connection opened" Jul 08 19:45:02 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:02+02:00" level=trace msg="starting accesspoint recv loop" Jul 08 19:45:02 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:02+02:00" level=trace msg="starting dealer recv loop" Jul 08 19:45:02 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:02+02:00" level=trace msg="received accesspoint ping" Jul 08 19:45:02 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:02+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 08 19:45:02 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:02+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 08 19:45:02 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:02+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 08 19:45:02 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:02+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 08 19:45:02 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:02+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 08 19:45:02 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:02+02:00" level=debug msg="received connection id: N2I3NDhiMDMtYjFiMi00MGFkLWIyNGUtNDE0YWIzNWU1MzVmK2RlYWxlcit0Y3A6Ly8wYWIxNTIwYS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQTQxNjg1RTdGRUUyODhEQkVFQTIzNTRBRDA0OTk0MTJFQUEzQjBEODI1NDVFNDAxQjQ0RkE5QkQyQkM2QjEyMQ==" Jul 08 19:45:02 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:02+02:00" level=trace msg="received accesspoint pong ack" Jul 08 19:45:02 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:02 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:02 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:02+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 08 19:45:02 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:02 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:03 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:03 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:03 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:03 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:04 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:04 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:04 rpi5-ws840 volumio[1423]: info: Initializing connection to go-librespot Websocket Jul 08 19:45:04 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:04+02:00" level=debug msg="new websocket client" Jul 08 19:45:04 rpi5-ws840 volumio[1423]: info: Connection to go-librespot Websocket established Jul 08 19:45:04 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:04 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:04 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:04 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:05 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:05 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:05 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:05 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Preload queue cleared Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioReplaceandPlayItems Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreStateMachine::ClearQueue Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreStateMachine::stop Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CorePlayQueue::clearPlayQueue Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CorePlayQueue::saveQueue Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioPushQueue Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreStateMachine::addQueueItems Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CorePlayQueue::addQueueItems Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Preload queue cleared Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:3DwQ7AH3xGD9h65ezslm6q Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Using cached record of: spotify:track:3DwQ7AH3xGD9h65ezslm6q Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:6QAsrXPnMSXIbV0yEJHlEX Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Using cached record of: spotify:track:6QAsrXPnMSXIbV0yEJHlEX Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioPushQueue Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CorePlayQueue::saveQueue Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreStateMachine::updateTrackBlock Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrackBlock Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioPlay Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreStateMachine::play index 1 Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreStateMachine::addQueueItems Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CorePlayQueue::addQueueItems Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Preload queue cleared Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:2MuWTIM3b0YEAskbeeFE1i Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Using cached record of: spotify:track:2MuWTIM3b0YEAskbeeFE1i Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:02xhLoVqpGmOqvolgrwM8w Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Using cached record of: spotify:track:02xhLoVqpGmOqvolgrwM8w Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:3LpHzQU2CZzZJGdUWV79SI Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Using cached record of: spotify:track:3LpHzQU2CZzZJGdUWV79SI Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:5lqyqPU3JkpCbUbLmTVQPW Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Using cached record of: spotify:track:5lqyqPU3JkpCbUbLmTVQPW Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:5ltXoDLlI0rFZAmOXbAp5T Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Using cached record of: spotify:track:5ltXoDLlI0rFZAmOXbAp5T Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:2R6UrJ8uWbSIiHWmvRQvN8 Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Using cached record of: spotify:track:2R6UrJ8uWbSIiHWmvRQvN8 Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:28WmNsclKsrVmdv3tDmoYU Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Using cached record of: spotify:track:28WmNsclKsrVmdv3tDmoYU Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Adding Item to queue: spotify:track:6FUwPb4mGlUDbx42uspXaZ Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Using cached record of: spotify:track:6FUwPb4mGlUDbx42uspXaZ Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreStateMachine::stop Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioPushQueue Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CorePlayQueue::saveQueue Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreStateMachine::play index undefined Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreStateMachine::updateTrackBlock Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrackBlock Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreStateMachine::startPlaybackTimer Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: [1751996706235] ControllerSpotify::clearAddPlayTrack Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Sending Spotify command with payload to local API: /player/play Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:06 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:06+02:00" level=debug msg="resolved context of track" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:45:06 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:06+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:45:06 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:06+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:45:06 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:06+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 19:45:06 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:06+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 19:45:06 rpi5-ws840 volumio[1423]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6QAsrXPnMSXIbV0yEJHlEX","play_origin":"go-librespot"}} Jul 08 19:45:06 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:06+02:00" level=debug msg="selected format OGG_VORBIS_320 (004b8a787e861e2a2df69a327ec9bfaae911c167)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:45:06 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:06+02:00" level=debug msg="requested aes key for file 004b8a787e861e2a2df69a327ec9bfaae911c167, gid: 6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:06 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:06+02:00" level=debug msg="fetched first chunk of 28, total size is 14354512 bytes" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:45:06 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:06+02:00" level=debug msg="created new output device" Jul 08 19:45:06 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:06+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Jul 08 19:45:06 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:06+02:00" level=debug msg="fetched chunk 1/27, size: 524288" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:45:06 rpi5-ws840 go-librespot[3391]: time="2025-07-08T19:45:06+02:00" level=info msg="loaded track \"Nothing Else Matters - Remastered 2021\" (paused: false, position: 0ms, duration: 388733ms, prefetched: false)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:45:06 rpi5-ws840 go-librespot[3391]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Jul 08 19:45:06 rpi5-ws840 go-librespot[3390]: Aborted Jul 08 19:45:06 rpi5-ws840 volumio[1423]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jul 08 19:45:06 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Jul 08 19:45:06 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 08 19:45:06 rpi5-ws840 volumio[1423]: info: Connection to go-librespot Websocket closed Jul 08 19:45:07 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:07 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:07 rpi5-ws840 volumio[1423]: info: CoreCommandRouter::volumioGetState Jul 08 19:45:07 rpi5-ws840 volumio[1423]: info: CorePlayQueue::getTrack 1 Jul 08 19:45:07 rpi5-ws840 volumio[1423]: info: Getting Spotify volume Jul 08 19:45:07 rpi5-ws840 volumio[1423]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 08 19:45:07 rpi5-ws840 volumio[1423]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 08 19:45:07 rpi5-ws840 volumio[1423]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jul 08 19:45:07 rpi5-ws840 volumio[1423]: errno: -111, Jul 08 19:45:07 rpi5-ws840 volumio[1423]: code: 'ECONNREFUSED', Jul 08 19:45:07 rpi5-ws840 volumio[1423]: syscall: 'connect', Jul 08 19:45:07 rpi5-ws840 volumio[1423]: address: '127.0.0.1', Jul 08 19:45:07 rpi5-ws840 volumio[1423]: port: 9879, Jul 08 19:45:07 rpi5-ws840 volumio[1423]: response: undefined Jul 08 19:45:07 rpi5-ws840 volumio[1423]: } Jul 08 19:45:07 rpi5-ws840 volumio[1423]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 08 19:45:07 rpi5-ws840 sudo[3429]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-07-08 19:44' Jul 08 19:45:07 rpi5-ws840 sudo[3429]: 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="f9454895cc8e2f1971c705a815a7226e021e37d7" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1fc282af1865fae9b40239cedf2cc17c112eef0d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Jun 28 16:48:46 UTC 2025" VOLUMIO_VERSION="4.014" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="1b557e4869cd2eea14f4113140ecea1c"