Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: Received OAUTH Data Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: Executing Spotify Oauth Login Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: Saving Spotify Refresh Token Jul 08 16:11:21 volumio1920x480 volumio[1433]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 08 16:11:21 volumio1920x480 volumio[1433]: SPOTIFY: BQB2Jv6G4Y3SotbGSeWdcjqi-MZPhtSDR8QojyYKvIuglz5zbOI1s2ONMS3iMrJaE0jSd80olpyYqheZjr14hRjv6cTClmXR4IJx_yxukkw0FwQGelF7_xRtXUIKEpb9YXYTt_xnROksWompZz-ULsudxLl6aS1HkzD6wYVFsAf1ZJdCz-ZmrXt5pzH3Dv0_Jrq_l1kqtV3KOnShMvt9DXJn-id84VuHF_nd2NoblcczSopLNN_Kc5ePyPeCwLdW6gqzgMh0e0QGTNtkIN1nJdejpgyTdjLIXHO6e_pDgCyWit3V0Ew Jul 08 16:11:21 volumio1920x480 volumio[1433]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: New Spotify access token = BQB2Jv6G4Y3SotbGSeWdcjqi-MZPhtSDR8QojyYKvIuglz5zbOI1s2ONMS3iMrJaE0jSd80olpyYqheZjr14hRjv6cTClmXR4IJx_yxukkw0FwQGelF7_xRtXUIKEpb9YXYTt_xnROksWompZz-ULsudxLl6aS1HkzD6wYVFsAf1ZJdCz-ZmrXt5pzH3Dv0_Jrq_l1kqtV3KOnShMvt9DXJn-id84VuHF_nd2NoblcczSopLNN_Kc5ePyPeCwLdW6gqzgMh0e0QGTNtkIN1nJdejpgyTdjLIXHO6e_pDgCyWit3V0Ew Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: Spotify credentials grant success - running version from March 24, 2019 Jul 08 16:11:21 volumio1920x480 volumio[1433]: SPOTIFY: User informations: {"country":"NG","display_name":"Lowerymichael","email":"lowerymichael1332@outlook.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31rpeznnia6zthzdlzxkalygovbe"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31rpeznnia6zthzdlzxkalygovbe","id":"31rpeznnia6zthzdlzxkalygovbe","images":[],"product":"premium","type":"user","uri":"spotify:user:31rpeznnia6zthzdlzxkalygovbe"} Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: Creating Spotify config file Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 16:11:21 volumio1920x480 sudo[2849]: volumio : unable to resolve host volumio1920x480: System error Jul 08 16:11:21 volumio1920x480 sudo[2851]: volumio : unable to resolve host volumio1920x480: System error Jul 08 16:11:21 volumio1920x480 sudo[2849]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 08 16:11:21 volumio1920x480 sudo[2851]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 08 16:11:21 volumio1920x480 sudo[2849]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 08 16:11:21 volumio1920x480 sudo[2851]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 08 16:11:21 volumio1920x480 sudo[2849]: pam_unix(sudo:session): session closed for user root Jul 08 16:11:21 volumio1920x480 sudo[2851]: pam_unix(sudo:session): session closed for user root Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: Spotify config file written Jul 08 16:11:21 volumio1920x480 sudo[2856]: volumio : unable to resolve host volumio1920x480: System error Jul 08 16:11:21 volumio1920x480 sudo[2856]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 08 16:11:21 volumio1920x480 sudo[2856]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 08 16:11:21 volumio1920x480 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: Connection to go-librespot Websocket closed Jul 08 16:11:21 volumio1920x480 systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Jul 08 16:11:21 volumio1920x480 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jul 08 16:11:21 volumio1920x480 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 08 16:11:21 volumio1920x480 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 08 16:11:21 volumio1920x480 go-librespot[2862]: go-librespot daemon starting... Jul 08 16:11:21 volumio1920x480 sudo[2856]: pam_unix(sudo:session): session closed for user root Jul 08 16:11:21 volumio1920x480 dbus-daemon[870]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.48' (uid=0 pid=2860 comm="timedatectl show --property=NTPSynchronized --valu") Jul 08 16:11:21 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:21+02:00" level=info msg="running go-librespot 0.2.0" Jul 08 16:11:21 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:21+02:00" level=debug msg="app state loaded" Jul 08 16:11:21 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:21+02:00" level=debug msg="stored credentials not found" Jul 08 16:11:21 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:21+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 08 16:11:21 volumio1920x480 systemd[1]: Starting systemd-timedated.service - Time & Date Service... Jul 08 16:11:21 volumio1920x480 volumio[1433]: verbose: New Socket.io Connection to 192.168.1.95 from 192.168.1.165 UA: Mozilla/5.0 (Linux; Android 15; CPH2581 Build/AP3A.240617.008; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/138.0.7204.45 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 12 Jul 08 16:11:21 volumio1920x480 volumio[1433]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 08 16:11:21 volumio1920x480 volumio[1433]: SPOTIFY: BQDrkBYO4z-AXRJqd0IqNdY37CoF70Z34cyzcurKI-UIDD4wWWSZAEf7vLOgOvw-ETASY1C92Z_E3qJ8tRaQthpduusvvNsnZZaog0-bNAUYUCVRW12S3iyJiw1fGmANz1YbaBbjoXd0e70gZ_GUxmuBaaQzIlSjpUUp0hDbNlm0pi6JlWROIo9KC4lCT_7HEn8e_XuIr-i_ozrTY-vNrSSiyD2q-Ko6uHyff02CSNKQ_ve8YY_WDTqmrDI9WNIttFow21d8HxshgmMv11pphr7EgBEifMevZrSqgUfJkwbZFzVsZX8 Jul 08 16:11:21 volumio1920x480 volumio[1433]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: New Spotify access token = BQDrkBYO4z-AXRJqd0IqNdY37CoF70Z34cyzcurKI-UIDD4wWWSZAEf7vLOgOvw-ETASY1C92Z_E3qJ8tRaQthpduusvvNsnZZaog0-bNAUYUCVRW12S3iyJiw1fGmANz1YbaBbjoXd0e70gZ_GUxmuBaaQzIlSjpUUp0hDbNlm0pi6JlWROIo9KC4lCT_7HEn8e_XuIr-i_ozrTY-vNrSSiyD2q-Ko6uHyff02CSNKQ_ve8YY_WDTqmrDI9WNIttFow21d8HxshgmMv11pphr7EgBEifMevZrSqgUfJkwbZFzVsZX8 Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: Spotify credentials grant success - running version from March 24, 2019 Jul 08 16:11:21 volumio1920x480 dbus-daemon[870]: [system] Successfully activated service 'org.freedesktop.timedate1' Jul 08 16:11:21 volumio1920x480 systemd[1]: Started systemd-timedated.service - Time & Date Service. Jul 08 16:11:21 volumio1920x480 setdatetime-helper.sh[2859]: Time is already synchronized. Jul 08 16:11:21 volumio1920x480 systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Jul 08 16:11:21 volumio1920x480 systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jul 08 16:11:21 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:21+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 16:11:21 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:21+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 16:11:21 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:21+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 16:11:21 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetVisibleSources Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetState Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 08 16:11:21 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:21+02:00" level=info msg="zeroconf server listening on port 42947" Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: Received Get System Info Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: Discovery: Getting this device information Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetState Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetState Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: Listing playlists Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jul 08 16:11:21 volumio1920x480 volumio[1433]: SPOTIFY: User informations: {"country":"NG","display_name":"Lowerymichael","email":"lowerymichael1332@outlook.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31rpeznnia6zthzdlzxkalygovbe"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31rpeznnia6zthzdlzxkalygovbe","id":"31rpeznnia6zthzdlzxkalygovbe","images":[],"product":"premium","type":"user","uri":"spotify:user:31rpeznnia6zthzdlzxkalygovbe"} Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: Spotify Successfully logged in Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: [1751983881926] CoreMusicLibrary::Adding element Spotify Jul 08 16:11:21 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 16:11:21 volumio1920x480 volumio[1433]: Cannot find translation for source YouTube Music Jul 08 16:11:21 volumio1920x480 volumio[1433]: Cannot find translation for source Spotify Jul 08 16:11:21 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:21+02:00" level=debug msg="obtained new client token: AAB3JGnd9B7d6J12olqbW+iK6cOVPd3kcbwUna6WoPddxJPWd2Z8m8ojx3kSbinaXvBxJbQIA9g/Y6iEFL3+FdMi01/3UDDI3XfRzo9RPcoxole0HB5PKw+DAR+oUNx4m6Enl3ZsmLBwHQK9tBzWdeeEZ1iRfTZUNrfFTciqkVDcliOvyz3b4PvcNL+6BNS9GiV40JtI9T6FrOXIj9TIzwFI/ECl6PPNw2pNL3pZzgMOOn+8R8dbosUjTw==" Jul 08 16:11:22 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=debug msg="completed keyexchange" Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=debug msg="completed challenge" Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=info msg="authenticated AP as 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=info msg="authenticated Login5 as 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=debug msg="stored credentials for 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=debug msg="initializing zeroconf session, username: 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=debug msg="dealer connection opened" Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=trace msg="starting accesspoint recv loop" Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=trace msg="starting dealer recv loop" Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=trace msg="received accesspoint ping" Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=debug msg="received connection id: MjY1YzU3MWYtMWQyMy00NWJjLTgxYjAtMTkzMTY4MWMwNDA1K2RlYWxlcit0Y3A6Ly8wYWIxNTA5NC5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArM0FCOTgwRENFNzRCMTQ2NDVFNzkxMjFDNTlBNjA1NEUxNkNFNzdBMzNFNzBCNzg2Q0E2QTk5RERBNkNGNUY5MQ==" Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=trace msg="received accesspoint pong ack" Jul 08 16:11:22 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:22+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 08 16:11:23 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jul 08 16:11:23 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jul 08 16:11:23 volumio1920x480 volumio[1433]: info: Received Get System Info Jul 08 16:11:23 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 16:11:23 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 16:11:23 volumio1920x480 volumio[1433]: info: Discovery: Getting this device information Jul 08 16:11:23 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetState Jul 08 16:11:23 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 16:11:24 volumio1920x480 volumio[1433]: info: Initializing connection to go-librespot Websocket Jul 08 16:11:24 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:24+02:00" level=debug msg="new websocket client" Jul 08 16:11:24 volumio1920x480 volumio[1433]: info: Connection to go-librespot Websocket established Jul 08 16:11:24 volumio1920x480 volumio[1433]: info: go-librespot daemon successfully initialized Jul 08 16:11:25 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jul 08 16:11:25 volumio1920x480 volumio[1433]: info: Received Get System Info Jul 08 16:11:25 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 16:11:25 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 16:11:25 volumio1920x480 volumio[1433]: info: Discovery: Getting this device information Jul 08 16:11:25 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetState Jul 08 16:11:25 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 16:11:27 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 16:11:27 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 16:11:27 volumio1920x480 volumio[1433]: info: Discovery: Getting this device information Jul 08 16:11:27 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetState Jul 08 16:11:27 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 16:11:27 volumio1920x480 volumio[1433]: info: Getting Spotify volume Jul 08 16:11:27 volumio1920x480 volumio[1433]: info: Spotify volume: 100 Jul 08 16:11:27 volumio1920x480 volumio[1433]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 13 Jul 08 16:11:27 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetState Jul 08 16:11:27 volumio1920x480 volumio[1433]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Jul 08 16:11:27 volumio1920x480 volumio[1433]: SPOTIFY: SPOTIFY VOLUME 100 Jul 08 16:11:27 volumio1920x480 volumio[1433]: SPOTIFY: VOLUMIO VOLUME 30 Jul 08 16:11:27 volumio1920x480 volumio[1433]: SPOTIFY: DELTA VOLUME ENOUGH: true Jul 08 16:11:27 volumio1920x480 volumio[1433]: info: Setting Spotify Volume from Volumio: 30 Jul 08 16:11:27 volumio1920x480 volumio[1433]: info: Initializing connection to go-librespot Websocket Jul 08 16:11:27 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:27+02:00" level=debug msg="new websocket client" Jul 08 16:11:27 volumio1920x480 volumio[1433]: info: Connection to go-librespot Websocket established Jul 08 16:11:29 volumio1920x480 volumio[1433]: SPOTIFY: SETTING SPOTIFY VOLUME 30 Jul 08 16:11:29 volumio1920x480 volumio[1433]: info: Sending Spotify command with payload to local API: /player/volume Jul 08 16:11:29 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:29+02:00" level=debug msg="update volume to 19660/65535" Jul 08 16:11:30 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:30+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jul 08 16:11:30 volumio1920x480 go-librespot[2863]: time="2025-07-08T16:11:30+02:00" level=trace msg="emitting websocket event: volume" Jul 08 16:11:30 volumio1920x480 volumio[1433]: SPOTIFY: received: {"type":"volume","data":{"value":30,"max":100}} Jul 08 16:11:30 volumio1920x480 volumio[1433]: SPOTIFY: RECEIVED SPOTIFY VOLUME 30 Jul 08 16:11:30 volumio1920x480 volumio[1433]: SPOTIFY: received: {"type":"volume","data":{"value":30,"max":100}} Jul 08 16:11:30 volumio1920x480 volumio[1433]: SPOTIFY: RECEIVED SPOTIFY VOLUME 30 Jul 08 16:11:30 volumio1920x480 volumio[1433]: info: Getting Spotify volume Jul 08 16:11:30 volumio1920x480 volumio[1433]: info: Spotify volume: 30 Jul 08 16:11:30 volumio1920x480 volumio[1433]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 13 Jul 08 16:11:30 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetState Jul 08 16:11:30 volumio1920x480 volumio[1433]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Jul 08 16:11:31 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jul 08 16:11:37 volumio1920x480 volumio[1433]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jul 08 16:11:37 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jul 08 16:11:37 volumio1920x480 volumio[1433]: info: Creating Spotify config file Jul 08 16:11:37 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 16:11:37 volumio1920x480 volumio[1433]: info: Spotify config file written Jul 08 16:11:37 volumio1920x480 sudo[2888]: volumio : unable to resolve host volumio1920x480: System error Jul 08 16:11:37 volumio1920x480 sudo[2888]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 08 16:11:37 volumio1920x480 sudo[2888]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 08 16:11:37 volumio1920x480 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jul 08 16:11:37 volumio1920x480 systemd[1]: go-librespot-daemon.service: Killing process 2864 (go-librespot) with signal SIGKILL. Jul 08 16:11:37 volumio1920x480 volumio[1433]: info: Connection to go-librespot Websocket closed Jul 08 16:11:37 volumio1920x480 volumio[1433]: info: Connection to go-librespot Websocket closed Jul 08 16:11:37 volumio1920x480 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jul 08 16:11:37 volumio1920x480 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 08 16:11:37 volumio1920x480 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 08 16:11:37 volumio1920x480 go-librespot[2890]: go-librespot daemon starting... Jul 08 16:11:37 volumio1920x480 sudo[2888]: pam_unix(sudo:session): session closed for user root Jul 08 16:11:37 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:37+02:00" level=info msg="running go-librespot 0.2.0" Jul 08 16:11:37 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:37+02:00" level=debug msg="app state loaded" Jul 08 16:11:37 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:37+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 08 16:11:37 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:37+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-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 08 16:11:37 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:37+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jul 08 16:11:37 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:37+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jul 08 16:11:37 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:37+02:00" level=info msg="zeroconf server listening on port 32941" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=debug msg="obtained new client token: AACusrAuM0aLgjLkFuzVetw5V4r/9cWE1EIw5fvM86yaKtIw/KRL69sFh+u8oSkbwTV2jufk/FlM3GEKFotszmQ7UILnet8yZbbnhm3p2WjOwWOO8pJo18syUT0mg1PYSmoXT3QJ8WEtybM8rkK/EmnAWqWS6JJLxMDEOWMBdV1ZZxPCLkYx3dAtOQx0TAgWw5AVU7/FAmLwCavixWzeYIRyG/c3DDtE8kf4kfSqmYGbkLCpwulkvXQ=" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=debug msg="completed keyexchange" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=debug msg="completed challenge" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=info msg="authenticated AP as 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=info msg="authenticated Login5 as 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=debug msg="initializing zeroconf session, username: 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=debug msg="dealer connection opened" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=trace msg="starting accesspoint recv loop" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=trace msg="starting dealer recv loop" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=trace msg="received accesspoint ping" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=debug msg="received connection id: NzQ1ZWY4NTQtZDcwNy00NDlmLWE2NDMtNzE3N2U3ODFiN2QzK2RlYWxlcit0Y3A6Ly8wYWIxNTIyMC5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQjlERUFEM0EzQUFBODNFQzlEQkUwRTJGRUFBRDNENTExN0Y2MTZCMDUzNDEzNDVDRDlGNTFGQjFCQkY2QjRCQQ==" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=trace msg="received accesspoint pong ack" Jul 08 16:11:38 volumio1920x480 go-librespot[2891]: time="2025-07-08T16:11:38+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 08 16:11:39 volumio1920x480 volumio[1433]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jul 08 16:11:39 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jul 08 16:11:39 volumio1920x480 volumio[1433]: info: Creating Spotify config file Jul 08 16:11:39 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 16:11:39 volumio1920x480 volumio[1433]: info: Spotify config file written Jul 08 16:11:39 volumio1920x480 sudo[2899]: volumio : unable to resolve host volumio1920x480: System error Jul 08 16:11:39 volumio1920x480 sudo[2899]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 08 16:11:39 volumio1920x480 sudo[2899]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 08 16:11:39 volumio1920x480 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jul 08 16:11:39 volumio1920x480 systemd[1]: go-librespot-daemon.service: Killing process 2895 (go-librespot) with signal SIGKILL. Jul 08 16:11:39 volumio1920x480 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jul 08 16:11:39 volumio1920x480 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 08 16:11:39 volumio1920x480 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 08 16:11:39 volumio1920x480 go-librespot[2901]: go-librespot daemon starting... Jul 08 16:11:39 volumio1920x480 sudo[2899]: pam_unix(sudo:session): session closed for user root Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=info msg="running go-librespot 0.2.0" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=debug msg="app state loaded" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+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 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+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 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+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 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=info msg="zeroconf server listening on port 35999" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=debug msg="obtained new client token: AAAjeJrcs96C7bNAXTbRP8bzaJefNsN4nWVSzeYyX/bQBjGUR7qm7pNPLcCvR5BMB4hE+LzTpysZuNweXu4tIqc/qJbQIXHI7Ao9uaRRWY+bGR2p/LPljLiOhmoJzH2uVDH7bmB1soPen/0+MyFbSQ6v3QJe2IGX2SpX0f7lb99qD9Nyai51AvUx6MahpvtiGRFKgIEF1amov5h5bmo5MlTBkHCt1d3B6LhSljXLo5CsCOQKKBLWT8HKqA==" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=debug msg="completed keyexchange" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=debug msg="completed challenge" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=info msg="authenticated AP as 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=info msg="authenticated Login5 as 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=debug msg="initializing zeroconf session, username: 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=debug msg="dealer connection opened" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=trace msg="starting accesspoint recv loop" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=trace msg="starting dealer recv loop" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=trace msg="received accesspoint ping" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=debug msg="received connection id: ZWRmODEwOWMtZTNkZS00NzFmLTllMzQtMGQ4YTA4N2Q1NjY1K2RlYWxlcit0Y3A6Ly8wYWIxNTFlYy5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArREEwMzAyQ0M5NkZDQTc3MkRFQ0Y1OTBDRkI2Mjc3MDVBQ0NDNDc2ODNBRUIzNzM0M0Y4Q0M2RDBCMkZDMENFNg==" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=trace msg="received accesspoint pong ack" Jul 08 16:11:39 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:39+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 08 16:11:40 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jul 08 16:11:40 volumio1920x480 volumio[1433]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jul 08 16:11:40 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jul 08 16:11:40 volumio1920x480 volumio[1433]: info: Received Get System Version Jul 08 16:11:40 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 08 16:11:40 volumio1920x480 volumio[1433]: info: Received Get System Info Jul 08 16:11:40 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 16:11:40 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 16:11:40 volumio1920x480 volumio[1433]: info: Discovery: Getting this device information Jul 08 16:11:40 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetState Jul 08 16:11:40 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 16:11:40 volumio1920x480 volumio[1433]: info: Initializing connection to go-librespot Websocket Jul 08 16:11:40 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:40+02:00" level=debug msg="new websocket client" Jul 08 16:11:40 volumio1920x480 volumio[1433]: info: Connection to go-librespot Websocket established Jul 08 16:11:40 volumio1920x480 volumio[1433]: info: go-librespot daemon successfully initialized Jul 08 16:11:41 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetQueue Jul 08 16:11:41 volumio1920x480 volumio[1433]: info: CoreStateMachine::getQueue Jul 08 16:11:41 volumio1920x480 volumio[1433]: info: CorePlayQueue::getQueue Jul 08 16:11:42 volumio1920x480 volumio[1433]: info: go-librespot daemon successfully initialized Jul 08 16:11:43 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jul 08 16:11:43 volumio1920x480 volumio[1433]: info: In handleBrowseUri, curUri=spotify Jul 08 16:11:43 volumio1920x480 volumio[1433]: info: Preload queue cleared Jul 08 16:11:43 volumio1920x480 volumio[1433]: info: Preload queue cleared Jul 08 16:11:43 volumio1920x480 volumio[1433]: info: Preload queue cleared Jul 08 16:11:43 volumio1920x480 volumio[1433]: info: Preload queue cleared Jul 08 16:11:43 volumio1920x480 volumio[1433]: info: Getting Spotify volume Jul 08 16:11:43 volumio1920x480 volumio[1433]: info: Spotify volume: 100 Jul 08 16:11:43 volumio1920x480 volumio[1433]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 13 Jul 08 16:11:43 volumio1920x480 volumio[1433]: info: Initializing connection to go-librespot Websocket Jul 08 16:11:43 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:43+02:00" level=debug msg="new websocket client" Jul 08 16:11:43 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetState Jul 08 16:11:43 volumio1920x480 volumio[1433]: info: Connection to go-librespot Websocket established Jul 08 16:11:43 volumio1920x480 volumio[1433]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Jul 08 16:11:43 volumio1920x480 volumio[1433]: SPOTIFY: SPOTIFY VOLUME 100 Jul 08 16:11:43 volumio1920x480 volumio[1433]: SPOTIFY: VOLUMIO VOLUME 30 Jul 08 16:11:43 volumio1920x480 volumio[1433]: SPOTIFY: DELTA VOLUME ENOUGH: true Jul 08 16:11:43 volumio1920x480 volumio[1433]: info: Setting Spotify Volume from Volumio: 30 Jul 08 16:11:45 volumio1920x480 volumio[1433]: info: Initializing connection to go-librespot Websocket Jul 08 16:11:45 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:45+02:00" level=debug msg="new websocket client" Jul 08 16:11:45 volumio1920x480 volumio[1433]: info: Connection to go-librespot Websocket established Jul 08 16:11:45 volumio1920x480 volumio[1433]: SPOTIFY: SETTING SPOTIFY VOLUME 30 Jul 08 16:11:45 volumio1920x480 volumio[1433]: info: Sending Spotify command with payload to local API: /player/volume Jul 08 16:11:45 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:45+02:00" level=debug msg="update volume to 19660/65535" Jul 08 16:11:45 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jul 08 16:11:45 volumio1920x480 volumio[1433]: info: In handleBrowseUri, curUri=spotify/myalbums Jul 08 16:11:45 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:45+02:00" level=debug msg="skipping dealer message" uri="hm://collection/ylpin/31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:11:45 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:45+02:00" level=debug msg="skipping dealer message" uri="hm://collection/ylpin/31rpeznnia6zthzdlzxkalygovbe/json" Jul 08 16:11:45 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:45+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 160" Jul 08 16:11:45 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:45+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 302" Jul 08 16:11:45 volumio1920x480 volumio[1433]: info: Preload queue cleared Jul 08 16:11:46 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:46+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jul 08 16:11:46 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:46+02:00" level=trace msg="emitting websocket event: volume" Jul 08 16:11:46 volumio1920x480 volumio[1433]: SPOTIFY: received: {"type":"volume","data":{"value":30,"max":100}} Jul 08 16:11:46 volumio1920x480 volumio[1433]: SPOTIFY: RECEIVED SPOTIFY VOLUME 30 Jul 08 16:11:46 volumio1920x480 volumio[1433]: SPOTIFY: received: {"type":"volume","data":{"value":30,"max":100}} Jul 08 16:11:46 volumio1920x480 volumio[1433]: SPOTIFY: RECEIVED SPOTIFY VOLUME 30 Jul 08 16:11:46 volumio1920x480 volumio[1433]: SPOTIFY: received: {"type":"volume","data":{"value":30,"max":100}} Jul 08 16:11:46 volumio1920x480 volumio[1433]: SPOTIFY: RECEIVED SPOTIFY VOLUME 30 Jul 08 16:11:46 volumio1920x480 volumio[1433]: info: Getting Spotify volume Jul 08 16:11:46 volumio1920x480 volumio[1433]: info: Spotify volume: 30 Jul 08 16:11:46 volumio1920x480 volumio[1433]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 13 Jul 08 16:11:46 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetState Jul 08 16:11:46 volumio1920x480 volumio[1433]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Jul 08 16:11:48 volumio1920x480 volumio[1433]: info: Getting Spotify volume Jul 08 16:11:48 volumio1920x480 volumio[1433]: info: Spotify volume: 30 Jul 08 16:11:48 volumio1920x480 volumio[1433]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 13 Jul 08 16:11:48 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetState Jul 08 16:11:48 volumio1920x480 volumio[1433]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Jul 08 16:11:51 volumio1920x480 systemd[1]: systemd-timedated.service: Deactivated successfully. Jul 08 16:11:52 volumio1920x480 volumio[1433]: info: Preload queue cleared Jul 08 16:11:52 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioReplaceandPlayItems Jul 08 16:11:52 volumio1920x480 volumio[1433]: info: CoreStateMachine::ClearQueue Jul 08 16:11:52 volumio1920x480 volumio[1433]: info: CoreStateMachine::stop Jul 08 16:11:52 volumio1920x480 volumio[1433]: info: CoreStateMachine::serviceStop Jul 08 16:11:52 volumio1920x480 volumio[1433]: info: Received STOP, but no service to execute it Jul 08 16:11:52 volumio1920x480 volumio[1433]: info: CorePlayQueue::clearPlayQueue Jul 08 16:11:52 volumio1920x480 volumio[1433]: info: CorePlayQueue::saveQueue Jul 08 16:11:52 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioPushQueue Jul 08 16:11:52 volumio1920x480 volumio[1433]: info: CoreStateMachine::addQueueItems Jul 08 16:11:52 volumio1920x480 volumio[1433]: info: CorePlayQueue::addQueueItems Jul 08 16:11:52 volumio1920x480 volumio[1433]: info: Preload queue cleared Jul 08 16:11:52 volumio1920x480 volumio[1433]: info: Adding Item to queue: spotify:playlist:37i9dQZF1DWZCOSaet9tpB Jul 08 16:11:52 volumio1920x480 volumio[1433]: info: Exploding uri spotify:playlist:37i9dQZF1DWZCOSaet9tpB in service spop Jul 08 16:11:52 volumio1920x480 volumio[1433]: SPOTIFY: EXPLODING URI:spotify:playlist:37i9dQZF1DWZCOSaet9tpB Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioPushQueue Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CorePlayQueue::saveQueue Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreStateMachine::updateTrackBlock Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrackBlock Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioPlay Jul 08 16:11:53 volumio1920x480 volumio[1433]: verbose: UNSET VOLATILE: Service: undefined Jul 08 16:11:53 volumio1920x480 volumio[1433]: ------------------------------------ BT MESSAGE: [FUNC] detachBluetooth Jul 08 16:11:53 volumio1920x480 volumio[1433]: ------------------------------------ BT MESSAGE: [FUNC] btAudioOutput Jul 08 16:11:53 volumio1920x480 volumio[1433]: ------------------------------------ BT MESSAGE: [dbus-next] Disabling Bluetooth Audio Output Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreStateMachine::play index 0 Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:11:53 volumio1920x480 volumio[1433]: ------------------------------------ BT MESSAGE: Bluetooth audio output disabled. Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreStateMachine::stop Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreStateMachine::resetVolumioState Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreStateMachine::getcurrentVolume Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioRetrievevolume Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreStateMachine::play index undefined Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioStop Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreStateMachine::stop Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrack 0 Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreStateMachine::startPlaybackTimer Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrack 0 Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: [1751983913192] ControllerSpotify::clearAddPlayTrack Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: Sending Spotify command with payload to local API: /player/play Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreStateMachine::pushState Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrack 0 Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioPushState Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetState Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrack 0 Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreStateMachine::updateTrackBlock Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrackBlock Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioRetrievevolume Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: PeppyMeterBasic ---peppymeterbasic status stop Jul 08 16:11:53 volumio1920x480 volumio[1433]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Jul 08 16:11:53 volumio1920x480 volumio[1433]: SPOTIFY: SPOTIFY VOLUME 30 Jul 08 16:11:53 volumio1920x480 volumio[1433]: SPOTIFY: VOLUMIO VOLUME 30 Jul 08 16:11:53 volumio1920x480 volumio[1433]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreStateMachine::pushState Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrack 0 Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioPushState Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetState Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrack 0 Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: PeppyMeterBasic ---peppymeterbasic status stop Jul 08 16:11:53 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:53+02:00" level=debug msg="resolved context of track" uri="spotify:track:3w0eFAME3IxlonearUIaXJ" Jul 08 16:11:53 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:53+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3w0eFAME3IxlonearUIaXJ" Jul 08 16:11:53 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:53+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3w0eFAME3IxlonearUIaXJ" Jul 08 16:11:53 volumio1920x480 volumio[1433]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Jul 08 16:11:53 volumio1920x480 volumio[1433]: SPOTIFY: SPOTIFY VOLUME 30 Jul 08 16:11:53 volumio1920x480 volumio[1433]: SPOTIFY: VOLUMIO VOLUME 30 Jul 08 16:11:53 volumio1920x480 volumio[1433]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 08 16:11:53 volumio1920x480 sudo[2952]: volumio : unable to resolve host volumio1920x480: System error Jul 08 16:11:53 volumio1920x480 sudo[2952]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Jul 08 16:11:53 volumio1920x480 sudo[2952]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 08 16:11:53 volumio1920x480 sudo[2954]: volumio : unable to resolve host volumio1920x480: System error Jul 08 16:11:53 volumio1920x480 sudo[2954]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Jul 08 16:11:53 volumio1920x480 sudo[2954]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 08 16:11:53 volumio1920x480 sudo[2952]: pam_unix(sudo:session): session closed for user root Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: peppymeterbasic Daemon Stop Jul 08 16:11:53 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:53+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 16:11:53 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:53+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 16:11:53 volumio1920x480 volumio[1433]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3w0eFAME3IxlonearUIaXJ","play_origin":"go-librespot"}} Jul 08 16:11:53 volumio1920x480 volumio[1433]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3w0eFAME3IxlonearUIaXJ","play_origin":"go-librespot"}} Jul 08 16:11:53 volumio1920x480 volumio[1433]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3w0eFAME3IxlonearUIaXJ","play_origin":"go-librespot"}} Jul 08 16:11:53 volumio1920x480 sudo[2954]: pam_unix(sudo:session): session closed for user root Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: peppymeterbasic Daemon Stop Jul 08 16:11:53 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:53+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Jul 08 16:11:53 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:53+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jul 08 16:11:53 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:53+02:00" level=debug msg="selected format OGG_VORBIS_320 (70d7aa318b4c0df2c0c9297c8aec784bab307c28)" uri="spotify:track:3w0eFAME3IxlonearUIaXJ" Jul 08 16:11:53 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:53+02:00" level=debug msg="requested aes key for file 70d7aa318b4c0df2c0c9297c8aec784bab307c28, gid: 3w0eFAME3IxlonearUIaXJ" Jul 08 16:11:53 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:53+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jul 08 16:11:53 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:53+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1391" Jul 08 16:11:53 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:53+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jul 08 16:11:53 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:53+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1144" Jul 08 16:11:53 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:53+02:00" level=debug msg="fetched first chunk of 15, total size is 7466563 bytes" uri="spotify:track:3w0eFAME3IxlonearUIaXJ" Jul 08 16:11:53 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:53+02:00" level=debug msg="created new output device" Jul 08 16:11:53 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:53+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 16:11:53 volumio1920x480 go-librespot[2902]: time="2025-07-08T16:11:53+02:00" level=info msg="loaded track \"Ewo\" (paused: false, position: 0ms, duration: 180765ms, prefetched: false)" uri="spotify:track:3w0eFAME3IxlonearUIaXJ" Jul 08 16:11:53 volumio1920x480 go-librespot[2902]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Jul 08 16:11:53 volumio1920x480 go-librespot[2901]: Aborted Jul 08 16:11:53 volumio1920x480 volumio[1433]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jul 08 16:11:53 volumio1920x480 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: Connection to go-librespot Websocket closed Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: Connection to go-librespot Websocket closed Jul 08 16:11:53 volumio1920x480 volumio[1433]: info: Connection to go-librespot Websocket closed Jul 08 16:11:53 volumio1920x480 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 08 16:11:56 volumio1920x480 volumio[1433]: info: Initializing connection to go-librespot Websocket Jul 08 16:11:56 volumio1920x480 volumio[1433]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 08 16:11:56 volumio1920x480 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jul 08 16:11:56 volumio1920x480 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 08 16:11:56 volumio1920x480 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 08 16:11:56 volumio1920x480 go-librespot[2960]: go-librespot daemon starting... Jul 08 16:11:56 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:56+02:00" level=info msg="running go-librespot 0.2.0" Jul 08 16:11:56 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:56+02:00" level=debug msg="app state loaded" Jul 08 16:11:56 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:56+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 08 16:11:56 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:56+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 16:11:56 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:56+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 16:11:56 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:56+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 16:11:56 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:56+02:00" level=info msg="zeroconf server listening on port 46333" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=debug msg="obtained new client token: AAAUmorVICo8tWXnCAMaIZFrem7CwP8e/lAB77jQkPdpvLaM+2tw3oBuY11Esn131AKIlci2PS8zbe7zhATDjO0peof6fKSr/zL5sFLymF+ERH2kQ+oQ62HDMZZlLdc/vdLgpoZEczS4UBNKGlSM2HXQ3Pfh5u5n5aILLheKohmuJatpxxnTb9PUBPZkqijlV3lAgjEGjUkziSaLk+FZ/HDYDpxW85oIcFS54acQ6LXswDXFjotGr2Q=" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=debug msg="completed keyexchange" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=debug msg="completed challenge" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=info msg="authenticated AP as 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=info msg="authenticated Login5 as 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=debug msg="initializing zeroconf session, username: 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=debug msg="dealer connection opened" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=trace msg="starting accesspoint recv loop" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=trace msg="starting dealer recv loop" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=trace msg="received accesspoint ping" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=debug msg="received connection id: MmQ4YjQ0YWYtMmFlYi00YjAzLWI0ZmItZjQ4ZTI2ZTI3N2YxK2RlYWxlcit0Y3A6Ly8wYWIxNTE2My5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArNzBENEFDQjA4OUE0OTEzNzJFM0U5QzRCNDU1OEJBQTk4MTg3NDQ0REJCQjM1RTcwQUUwRURCQkEwM0NCQjAwOQ==" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=trace msg="received accesspoint pong ack" Jul 08 16:11:57 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:57+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 08 16:11:57 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 16:11:57 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 16:11:57 volumio1920x480 volumio[1433]: info: Discovery: Getting this device information Jul 08 16:11:57 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetState Jul 08 16:11:57 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrack 0 Jul 08 16:11:57 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 16:11:59 volumio1920x480 volumio[1433]: info: Initializing connection to go-librespot Websocket Jul 08 16:11:59 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:11:59+02:00" level=debug msg="new websocket client" Jul 08 16:11:59 volumio1920x480 volumio[1433]: info: Connection to go-librespot Websocket established Jul 08 16:12:02 volumio1920x480 volumio[1433]: info: Getting Spotify volume Jul 08 16:12:02 volumio1920x480 volumio[1433]: info: Spotify volume: 100 Jul 08 16:12:02 volumio1920x480 volumio[1433]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 13 Jul 08 16:12:02 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetState Jul 08 16:12:02 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrack 0 Jul 08 16:12:02 volumio1920x480 volumio[1433]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Jul 08 16:12:02 volumio1920x480 volumio[1433]: SPOTIFY: SPOTIFY VOLUME 100 Jul 08 16:12:02 volumio1920x480 volumio[1433]: SPOTIFY: VOLUMIO VOLUME 30 Jul 08 16:12:02 volumio1920x480 volumio[1433]: SPOTIFY: DELTA VOLUME ENOUGH: true Jul 08 16:12:02 volumio1920x480 volumio[1433]: info: Setting Spotify Volume from Volumio: 30 Jul 08 16:12:04 volumio1920x480 volumio[1433]: SPOTIFY: SETTING SPOTIFY VOLUME 30 Jul 08 16:12:04 volumio1920x480 volumio[1433]: info: Sending Spotify command with payload to local API: /player/volume Jul 08 16:12:04 volumio1920x480 volumio[1433]: error: Failed to send command to Spotify local API: /player/volume: Error: Bad Request Jul 08 16:12:07 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioNext Jul 08 16:12:07 volumio1920x480 volumio[1433]: info: CoreStateMachine::next Jul 08 16:12:07 volumio1920x480 volumio[1433]: info: CoreStateMachine::stop Jul 08 16:12:07 volumio1920x480 volumio[1433]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:12:07 volumio1920x480 volumio[1433]: info: CoreStateMachine::play index undefined Jul 08 16:12:07 volumio1920x480 volumio[1433]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:12:07 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrack 1 Jul 08 16:12:07 volumio1920x480 volumio[1433]: info: CoreStateMachine::startPlaybackTimer Jul 08 16:12:07 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrack 1 Jul 08 16:12:07 volumio1920x480 volumio[1433]: info: [1751983927187] ControllerSpotify::clearAddPlayTrack Jul 08 16:12:07 volumio1920x480 volumio[1433]: info: Sending Spotify command with payload to local API: /player/play Jul 08 16:12:07 volumio1920x480 volumio[1433]: info: CoreStateMachine::updateTrackBlock Jul 08 16:12:07 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrackBlock Jul 08 16:12:07 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:12:07+02:00" level=debug msg="resolved context of track" uri="spotify:track:4sm7xhaW2PT4iLuTtXaKa1" Jul 08 16:12:07 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:12:07+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4sm7xhaW2PT4iLuTtXaKa1" Jul 08 16:12:07 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:12:07+02:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:4sm7xhaW2PT4iLuTtXaKa1" Jul 08 16:12:07 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:12:07+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 16:12:07 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:12:07+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 16:12:07 volumio1920x480 volumio[1433]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4sm7xhaW2PT4iLuTtXaKa1","play_origin":"go-librespot"}} Jul 08 16:12:07 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:12:07+02:00" level=debug msg="selected format OGG_VORBIS_320 (928d7a2a583720bcdfc661fd9013bc29fa826daf)" uri="spotify:track:4sm7xhaW2PT4iLuTtXaKa1" Jul 08 16:12:07 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:12:07+02:00" level=debug msg="requested aes key for file 928d7a2a583720bcdfc661fd9013bc29fa826daf, gid: 4sm7xhaW2PT4iLuTtXaKa1" Jul 08 16:12:07 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:12:07+02:00" level=debug msg="fetched first chunk of 22, total size is 11205989 bytes" uri="spotify:track:4sm7xhaW2PT4iLuTtXaKa1" Jul 08 16:12:07 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:12:07+02:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:4sm7xhaW2PT4iLuTtXaKa1" Jul 08 16:12:07 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:12:07+02:00" level=debug msg="created new output device" Jul 08 16:12:07 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:12:07+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 16:12:07 volumio1920x480 go-librespot[2961]: time="2025-07-08T16:12:07+02:00" level=info msg="loaded track \"99 (feat. Daecolm)\" (paused: false, position: 1ms, duration: 248832ms, prefetched: false)" uri="spotify:track:4sm7xhaW2PT4iLuTtXaKa1" Jul 08 16:12:07 volumio1920x480 go-librespot[2961]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Jul 08 16:12:07 volumio1920x480 go-librespot[2960]: Aborted Jul 08 16:12:07 volumio1920x480 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Jul 08 16:12:07 volumio1920x480 volumio[1433]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jul 08 16:12:07 volumio1920x480 volumio[1433]: info: Connection to go-librespot Websocket closed Jul 08 16:12:07 volumio1920x480 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 08 16:12:10 volumio1920x480 volumio[1433]: info: Initializing connection to go-librespot Websocket Jul 08 16:12:10 volumio1920x480 volumio[1433]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 08 16:12:10 volumio1920x480 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jul 08 16:12:10 volumio1920x480 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 08 16:12:10 volumio1920x480 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 08 16:12:10 volumio1920x480 go-librespot[2984]: go-librespot daemon starting... Jul 08 16:12:10 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:10+02:00" level=info msg="running go-librespot 0.2.0" Jul 08 16:12:10 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:10+02:00" level=debug msg="app state loaded" Jul 08 16:12:10 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:10+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 08 16:12:10 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:10+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 08 16:12:10 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:10+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jul 08 16:12:10 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:10+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jul 08 16:12:10 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:10+02:00" level=info msg="zeroconf server listening on port 43867" Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=debug msg="obtained new client token: AADX6qU8pBWUML+PdixWzKElRqVJEpfJpMoSUfoGi1ZFN4OAlCga8sifd0xBQ1VrD68yUwrNKp3w9lZlNuoUUI1BRVo6nlbQiH4X1P/VH7UfUCo/irlvcyZV7cKkbWM8QTecicCWV8to+nkhFte6LOhZA6wzXjlq3aWknFue49PTECc7fRBm4ygirjmvB/UxXV+Aj0XkUtBtttvY2Mc6rGG+kjFeyhvGTDzsqNbZePbPYAGtLnHWSKQ=" Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=debug msg="completed keyexchange" Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=debug msg="completed challenge" Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=info msg="authenticated AP as 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=info msg="authenticated Login5 as 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=debug msg="initializing zeroconf session, username: 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:12:11 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Jul 08 16:12:11 volumio1920x480 volumio[1433]: info: CURURI: music-library Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=debug msg="dealer connection opened" Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=trace msg="starting accesspoint recv loop" Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=trace msg="starting dealer recv loop" Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=trace msg="received accesspoint ping" Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=debug msg="received connection id: MTcxMDRiNmEtM2E1ZC00ZDFmLTkzNjMtYmNmYTQ4MzVkNGU3K2RlYWxlcit0Y3A6Ly8wYWIxNTFmNi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArM0U4MEYxOTc4Nzk5M0IxQUM3N0ZCMjg0ODgwMDI3NjgxNDI3QkQwNUZFNTVFQUJFRURGRDVCNjUxNTE1MDVBNA==" Jul 08 16:12:11 volumio1920x480 volumio[1433]: info: Preload queue cleared Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=trace msg="received accesspoint pong ack" Jul 08 16:12:11 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:11+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 08 16:12:12 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Jul 08 16:12:12 volumio1920x480 volumio[1433]: info: CURURI: music-library/NAS Jul 08 16:12:12 volumio1920x480 volumio[1433]: info: Preload queue cleared Jul 08 16:12:12 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Jul 08 16:12:12 volumio1920x480 volumio[1433]: info: CURURI: music-library/NAS/Music_GP Jul 08 16:12:13 volumio1920x480 volumio[1433]: info: Preload queue cleared Jul 08 16:12:13 volumio1920x480 volumio[1433]: info: Initializing connection to go-librespot Websocket Jul 08 16:12:13 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:13+02:00" level=debug msg="new websocket client" Jul 08 16:12:13 volumio1920x480 volumio[1433]: info: Connection to go-librespot Websocket established Jul 08 16:12:16 volumio1920x480 volumio[1433]: info: Getting Spotify volume Jul 08 16:12:16 volumio1920x480 volumio[1433]: info: Spotify volume: 100 Jul 08 16:12:16 volumio1920x480 volumio[1433]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 13 Jul 08 16:12:16 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetState Jul 08 16:12:16 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrack 1 Jul 08 16:12:16 volumio1920x480 volumio[1433]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Jul 08 16:12:16 volumio1920x480 volumio[1433]: SPOTIFY: SPOTIFY VOLUME 100 Jul 08 16:12:16 volumio1920x480 volumio[1433]: SPOTIFY: VOLUMIO VOLUME 30 Jul 08 16:12:16 volumio1920x480 volumio[1433]: SPOTIFY: DELTA VOLUME ENOUGH: true Jul 08 16:12:16 volumio1920x480 volumio[1433]: info: Setting Spotify Volume from Volumio: 30 Jul 08 16:12:16 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jul 08 16:12:16 volumio1920x480 volumio[1433]: info: In handleBrowseUri, curUri=spotify Jul 08 16:12:16 volumio1920x480 volumio[1433]: info: Preload queue cleared Jul 08 16:12:16 volumio1920x480 volumio[1433]: info: Preload queue cleared Jul 08 16:12:16 volumio1920x480 volumio[1433]: info: Preload queue cleared Jul 08 16:12:16 volumio1920x480 volumio[1433]: info: Preload queue cleared Jul 08 16:12:18 volumio1920x480 volumio[1433]: SPOTIFY: SETTING SPOTIFY VOLUME 30 Jul 08 16:12:18 volumio1920x480 volumio[1433]: info: Sending Spotify command with payload to local API: /player/volume Jul 08 16:12:18 volumio1920x480 volumio[1433]: error: Failed to send command to Spotify local API: /player/volume: Error: Bad Request Jul 08 16:12:22 volumio1920x480 volumio[1433]: info: Preload queue cleared Jul 08 16:12:22 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioReplaceandPlayItems Jul 08 16:12:22 volumio1920x480 volumio[1433]: info: CoreStateMachine::ClearQueue Jul 08 16:12:22 volumio1920x480 volumio[1433]: info: CoreStateMachine::stop Jul 08 16:12:22 volumio1920x480 volumio[1433]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:12:22 volumio1920x480 volumio[1433]: info: CorePlayQueue::clearPlayQueue Jul 08 16:12:22 volumio1920x480 volumio[1433]: info: CorePlayQueue::saveQueue Jul 08 16:12:22 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioPushQueue Jul 08 16:12:22 volumio1920x480 volumio[1433]: info: CoreStateMachine::addQueueItems Jul 08 16:12:22 volumio1920x480 volumio[1433]: info: CorePlayQueue::addQueueItems Jul 08 16:12:22 volumio1920x480 volumio[1433]: info: Preload queue cleared Jul 08 16:12:22 volumio1920x480 volumio[1433]: info: Adding Item to queue: spotify:playlist:37i9dQZF1DX0kPgPjaCH1l Jul 08 16:12:22 volumio1920x480 volumio[1433]: info: Exploding uri spotify:playlist:37i9dQZF1DX0kPgPjaCH1l in service spop Jul 08 16:12:22 volumio1920x480 volumio[1433]: SPOTIFY: EXPLODING URI:spotify:playlist:37i9dQZF1DX0kPgPjaCH1l Jul 08 16:12:23 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioPushQueue Jul 08 16:12:23 volumio1920x480 volumio[1433]: info: CorePlayQueue::saveQueue Jul 08 16:12:23 volumio1920x480 volumio[1433]: info: CoreStateMachine::updateTrackBlock Jul 08 16:12:23 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrackBlock Jul 08 16:12:23 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioPlay Jul 08 16:12:23 volumio1920x480 volumio[1433]: info: CoreStateMachine::play index 0 Jul 08 16:12:23 volumio1920x480 volumio[1433]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:12:23 volumio1920x480 volumio[1433]: info: CoreStateMachine::stop Jul 08 16:12:23 volumio1920x480 volumio[1433]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:12:23 volumio1920x480 volumio[1433]: info: CoreStateMachine::play index undefined Jul 08 16:12:23 volumio1920x480 volumio[1433]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:12:23 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrack 0 Jul 08 16:12:23 volumio1920x480 volumio[1433]: info: CoreStateMachine::startPlaybackTimer Jul 08 16:12:23 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrack 0 Jul 08 16:12:23 volumio1920x480 volumio[1433]: info: [1751983943368] ControllerSpotify::clearAddPlayTrack Jul 08 16:12:23 volumio1920x480 volumio[1433]: info: Sending Spotify command with payload to local API: /player/play Jul 08 16:12:23 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:23+02:00" level=debug msg="resolved context of track" uri="spotify:track:75NaRkat24l3uKOyfymyzJ" Jul 08 16:12:23 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:23+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:75NaRkat24l3uKOyfymyzJ" Jul 08 16:12:23 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:23+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:75NaRkat24l3uKOyfymyzJ" Jul 08 16:12:23 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:23+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 16:12:23 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:23+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 16:12:23 volumio1920x480 volumio[1433]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:75NaRkat24l3uKOyfymyzJ","play_origin":"go-librespot"}} Jul 08 16:12:23 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:23+02:00" level=debug msg="selected format OGG_VORBIS_320 (6d820e3f75084f53fb95124fb0781966a41e865c)" uri="spotify:track:75NaRkat24l3uKOyfymyzJ" Jul 08 16:12:23 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:23+02:00" level=debug msg="requested aes key for file 6d820e3f75084f53fb95124fb0781966a41e865c, gid: 75NaRkat24l3uKOyfymyzJ" Jul 08 16:12:23 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:23+02:00" level=debug msg="fetched first chunk of 18, total size is 9200793 bytes" uri="spotify:track:75NaRkat24l3uKOyfymyzJ" Jul 08 16:12:23 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:23+02:00" level=debug msg="created new output device" Jul 08 16:12:23 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:23+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 16:12:23 volumio1920x480 go-librespot[2985]: time="2025-07-08T16:12:23+02:00" level=info msg="loaded track \"Free\" (paused: false, position: 0ms, duration: 211756ms, prefetched: false)" uri="spotify:track:75NaRkat24l3uKOyfymyzJ" Jul 08 16:12:23 volumio1920x480 go-librespot[2985]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Jul 08 16:12:23 volumio1920x480 go-librespot[2984]: Aborted Jul 08 16:12:23 volumio1920x480 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Jul 08 16:12:23 volumio1920x480 volumio[1433]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jul 08 16:12:23 volumio1920x480 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 08 16:12:23 volumio1920x480 volumio[1433]: info: Connection to go-librespot Websocket closed Jul 08 16:12:23 volumio1920x480 systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Jul 08 16:12:23 volumio1920x480 dbus-daemon[870]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.50' (uid=0 pid=3026 comm="timedatectl show --property=NTPSynchronized --valu") Jul 08 16:12:23 volumio1920x480 systemd[1]: Starting systemd-timedated.service - Time & Date Service... Jul 08 16:12:23 volumio1920x480 dbus-daemon[870]: [system] Successfully activated service 'org.freedesktop.timedate1' Jul 08 16:12:23 volumio1920x480 systemd[1]: Started systemd-timedated.service - Time & Date Service. Jul 08 16:12:23 volumio1920x480 setdatetime-helper.sh[3025]: Time is already synchronized. Jul 08 16:12:23 volumio1920x480 systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Jul 08 16:12:23 volumio1920x480 systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Jul 08 16:12:26 volumio1920x480 volumio[1433]: info: Initializing connection to go-librespot Websocket Jul 08 16:12:26 volumio1920x480 volumio[1433]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 08 16:12:27 volumio1920x480 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jul 08 16:12:27 volumio1920x480 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 08 16:12:27 volumio1920x480 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 08 16:12:27 volumio1920x480 go-librespot[3029]: go-librespot daemon starting... Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=info msg="running go-librespot 0.2.0" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=debug msg="app state loaded" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+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 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+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 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+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 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=info msg="zeroconf server listening on port 43305" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=debug msg="obtained new client token: AABMErsxcGLaFw9SmnKq047w97dWIC4eXSMNCgfI+l7EdOS1RaJ4tPuUbME45lDgmh/86TURAYpR5g9VUu4Mk6lv+J/7TacxAeYFulzHPIemyuQ9FC35LhA+/YsQlTNqGUMoIJwMqC1M4flZ9VRHufEKjGv1Af59BjTbjms2gDsuvxnXwR5Ihx0In/aVb9XxWQky0O7mNaJcIv5/A4MztVPTfbIqikvP6fKjYLy6AtoBUmHXmqWYv3nvuQ==" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=debug msg="completed keyexchange" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=debug msg="completed challenge" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=info msg="authenticated AP as 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=info msg="authenticated Login5 as 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=debug msg="initializing zeroconf session, username: 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:12:27 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 16:12:27 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 16:12:27 volumio1920x480 volumio[1433]: info: Discovery: Getting this device information Jul 08 16:12:27 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioGetState Jul 08 16:12:27 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrack 0 Jul 08 16:12:27 volumio1920x480 volumio[1433]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=debug msg="dealer connection opened" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=trace msg="starting accesspoint recv loop" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=trace msg="starting dealer recv loop" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=trace msg="received accesspoint ping" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=debug msg="received connection id: ODE4M2U1YzUtNmMwYi00NGZjLTk0MzEtYzc3MjdkNGJkOGE3K2RlYWxlcit0Y3A6Ly8wYWIxNTBhMC5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArRjE5NkQ4RTQ3Nzg0NzRDMTc4MEFCRjUwNzIxRjhCN0U0NTZFRjM3MjM2MjE4NzYwREJFOTFBMzQwQjU0NTRDMw==" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=trace msg="received accesspoint pong ack" Jul 08 16:12:27 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:27+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 08 16:12:29 volumio1920x480 volumio[1433]: info: Initializing connection to go-librespot Websocket Jul 08 16:12:29 volumio1920x480 volumio[1433]: info: Connection to go-librespot Websocket established Jul 08 16:12:29 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:29+02:00" level=debug msg="new websocket client" Jul 08 16:12:29 volumio1920x480 volumio[1433]: info: CoreCommandRouter::volumioNext Jul 08 16:12:29 volumio1920x480 volumio[1433]: info: CoreStateMachine::next Jul 08 16:12:29 volumio1920x480 volumio[1433]: info: CoreStateMachine::stop Jul 08 16:12:29 volumio1920x480 volumio[1433]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:12:29 volumio1920x480 volumio[1433]: info: CoreStateMachine::play index undefined Jul 08 16:12:29 volumio1920x480 volumio[1433]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:12:29 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrack 1 Jul 08 16:12:29 volumio1920x480 volumio[1433]: info: CoreStateMachine::startPlaybackTimer Jul 08 16:12:29 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrack 1 Jul 08 16:12:29 volumio1920x480 volumio[1433]: info: [1751983949982] ControllerSpotify::clearAddPlayTrack Jul 08 16:12:29 volumio1920x480 volumio[1433]: info: Sending Spotify command with payload to local API: /player/play Jul 08 16:12:29 volumio1920x480 volumio[1433]: info: CoreStateMachine::updateTrackBlock Jul 08 16:12:29 volumio1920x480 volumio[1433]: info: CorePlayQueue::getTrackBlock Jul 08 16:12:30 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:30+02:00" level=debug msg="resolved context of track" uri="spotify:track:5nmYNuBSh99LNDdZ0iSe2O" Jul 08 16:12:30 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:30+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:5nmYNuBSh99LNDdZ0iSe2O" Jul 08 16:12:30 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:30+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5nmYNuBSh99LNDdZ0iSe2O" Jul 08 16:12:30 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:30+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 16:12:30 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:30+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 16:12:30 volumio1920x480 volumio[1433]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5nmYNuBSh99LNDdZ0iSe2O","play_origin":"go-librespot"}} Jul 08 16:12:30 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:30+02:00" level=debug msg="selected format OGG_VORBIS_320 (d9f7650f8aed4afc9dc4ba0bdb7520edb7bb2c76)" uri="spotify:track:5nmYNuBSh99LNDdZ0iSe2O" Jul 08 16:12:30 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:30+02:00" level=debug msg="requested aes key for file d9f7650f8aed4afc9dc4ba0bdb7520edb7bb2c76, gid: 5nmYNuBSh99LNDdZ0iSe2O" Jul 08 16:12:30 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:30+02:00" level=debug msg="fetched first chunk of 17, total size is 8566593 bytes" uri="spotify:track:5nmYNuBSh99LNDdZ0iSe2O" Jul 08 16:12:30 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:30+02:00" level=debug msg="created new output device" Jul 08 16:12:30 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:30+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 16:12:30 volumio1920x480 go-librespot[3030]: time="2025-07-08T16:12:30+02:00" level=info msg="loaded track \"Get Better\" (paused: false, position: 0ms, duration: 195600ms, prefetched: false)" uri="spotify:track:5nmYNuBSh99LNDdZ0iSe2O" Jul 08 16:12:30 volumio1920x480 go-librespot[3030]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Jul 08 16:12:30 volumio1920x480 go-librespot[3029]: Aborted Jul 08 16:12:30 volumio1920x480 volumio[1433]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jul 08 16:12:30 volumio1920x480 volumio[1433]: info: Connection to go-librespot Websocket closed Jul 08 16:12:30 volumio1920x480 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Jul 08 16:12:30 volumio1920x480 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 08 16:12:32 volumio1920x480 volumio[1433]: info: Getting Spotify volume Jul 08 16:12:32 volumio1920x480 volumio[1433]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 08 16:12:32 volumio1920x480 volumio[1433]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 08 16:12:32 volumio1920x480 volumio[1433]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jul 08 16:12:32 volumio1920x480 volumio[1433]: errno: -111, Jul 08 16:12:32 volumio1920x480 volumio[1433]: code: 'ECONNREFUSED', Jul 08 16:12:32 volumio1920x480 volumio[1433]: syscall: 'connect', Jul 08 16:12:32 volumio1920x480 volumio[1433]: address: '127.0.0.1', Jul 08 16:12:32 volumio1920x480 volumio[1433]: port: 9879, Jul 08 16:12:32 volumio1920x480 volumio[1433]: response: undefined Jul 08 16:12:32 volumio1920x480 volumio[1433]: } Jul 08 16:12:32 volumio1920x480 volumio[1433]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 08 16:12:33 volumio1920x480 sudo[3067]: volumio : unable to resolve host volumio1920x480: System error Jul 08 16:12:33 volumio1920x480 sudo[3067]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-07-08 16:11' Jul 08 16:12:33 volumio1920x480 sudo[3067]: 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="4f980d5cf693b4272997a2fa2da8bb8036ddf1ab" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="811ff8312d42f9da0260be1d353081a805678820" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Jul 5 02:50:33 UTC 2025" VOLUMIO_VERSION="4.015" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d42ab79cc13d24482826e04fda2e8350"