-- Logs begin at Thu 2019-02-14 08:11:58 -02, end at Tue 2025-03-04 13:15:59 -03. -- Mar 04 13:14:00 volumio volumio[4736]: info: go-librespot daemon successfully initialized Mar 04 13:14:03 volumio volumio[4736]: info: Initializing connection to go-librespot Websocket Mar 04 13:14:03 volumio go-librespot[11172]: time="2025-03-04T13:14:03-03:00" level=debug msg="new websocket client" Mar 04 13:14:03 volumio volumio[4736]: info: Connection to go-librespot Websocket established Mar 04 13:14:06 volumio volumio[4736]: info: Getting Spotify volume Mar 04 13:14:06 volumio volumio[4736]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Mar 04 13:14:06 volumio volumio[4736]: info: CoreCommandRouter::volumioGetState Mar 04 13:14:06 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:14:09 volumio volumio[4736]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 04 13:14:16 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 04 13:14:16 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 04 13:14:16 volumio volumio[4736]: info: Discovery: Getting this device information Mar 04 13:14:16 volumio volumio[4736]: info: CoreCommandRouter::volumioGetState Mar 04 13:14:16 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:14:16 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 04 13:14:29 volumio volumio[4736]: info: Received OAUTH Data Mar 04 13:14:29 volumio volumio[4736]: info: Executing Spotify Oauth Login Mar 04 13:14:29 volumio volumio[4736]: info: Saving Spotify Refresh Token Mar 04 13:14:29 volumio sudo[11292]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 04 13:14:29 volumio sudo[11292]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 04 13:14:29 volumio sudo[11292]: pam_unix(sudo:session): session closed for user root Mar 04 13:14:29 volumio sudo[11295]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 04 13:14:29 volumio sudo[11295]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 04 13:14:29 volumio sudo[11295]: pam_unix(sudo:session): session closed for user root Mar 04 13:14:29 volumio volumio[4736]: verbose: New Socket.io Connection to 192.168.1.13 from 192.168.1.18 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_4 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 6 Mar 04 13:14:29 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 04 13:14:29 volumio volumio[4736]: info: CoreCommandRouter::volumioGetVisibleSources Mar 04 13:14:29 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 04 13:14:29 volumio volumio[4736]: info: CoreCommandRouter::volumioGetState Mar 04 13:14:29 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:14:29 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 04 13:14:29 volumio volumio[4736]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 04 13:14:29 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 04 13:14:29 volumio volumio[4736]: info: Received Get System Info Mar 04 13:14:29 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 04 13:14:29 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 04 13:14:29 volumio volumio[4736]: info: Discovery: Getting this device information Mar 04 13:14:29 volumio volumio[4736]: info: CoreCommandRouter::volumioGetState Mar 04 13:14:29 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:14:29 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 04 13:14:29 volumio volumio[4736]: info: CoreCommandRouter::volumioGetState Mar 04 13:14:29 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:14:29 volumio volumio[4736]: info: Listing playlists Mar 04 13:14:29 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 04 13:14:29 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 04 13:14:29 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 04 13:14:29 volumio volumio[4736]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 04 13:14:29 volumio volumio[4736]: SPOTIFY: BQDpkFAeZ9l7bqk1FeWO4U7Nm6CTRYYpQkJE58scytoYi-KE_l0MBiE215mKSKJnSrlCNebvvinB80ssB-b63UNqIcnUC_nAsLIqOZiE2rfmeXCWJNSQ5XRQ4WAlzTsRqxrOV_Gl6Ioex53thCCi7PefidOLorSXNhc2MY3Tle2Fnd9vKVdrr_p45LjBndUjhlIcRXXMhM-bG2S5ZnPol9weexZTsU8jcqv2DaTwKEed1O4zJxHmmK4ytNaEq1_6zHOmumWAO_Mf3FtDHcyN3hqhifrRowF5c0MgRgMSUiA Mar 04 13:14:29 volumio volumio[4736]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 04 13:14:29 volumio volumio[4736]: info: New Spotify access token = BQDpkFAeZ9l7bqk1FeWO4U7Nm6CTRYYpQkJE58scytoYi-KE_l0MBiE215mKSKJnSrlCNebvvinB80ssB-b63UNqIcnUC_nAsLIqOZiE2rfmeXCWJNSQ5XRQ4WAlzTsRqxrOV_Gl6Ioex53thCCi7PefidOLorSXNhc2MY3Tle2Fnd9vKVdrr_p45LjBndUjhlIcRXXMhM-bG2S5ZnPol9weexZTsU8jcqv2DaTwKEed1O4zJxHmmK4ytNaEq1_6zHOmumWAO_Mf3FtDHcyN3hqhifrRowF5c0MgRgMSUiA Mar 04 13:14:29 volumio volumio[4736]: info: Spotify credentials grant success - running version from March 24, 2019 Mar 04 13:14:29 volumio volumio[4736]: SPOTIFY: User informations: {"country":"BR","display_name":"Rocco","email":"parrobras@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31jnbekbdkd7zleaipqxoyu53e2i"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31jnbekbdkd7zleaipqxoyu53e2i","id":"31jnbekbdkd7zleaipqxoyu53e2i","images":[],"product":"premium","type":"user","uri":"spotify:user:31jnbekbdkd7zleaipqxoyu53e2i"} Mar 04 13:14:29 volumio volumio[4736]: info: Creating Spotify config file Mar 04 13:14:29 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 04 13:14:29 volumio volumio[4736]: info: Spotify config file written Mar 04 13:14:29 volumio sudo[11298]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 04 13:14:29 volumio sudo[11298]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 04 13:14:29 volumio systemd[1]: Stopping go-librespot Daemon... Mar 04 13:14:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Mar 04 13:14:29 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Mar 04 13:14:29 volumio systemd[1]: Stopped go-librespot Daemon. Mar 04 13:14:29 volumio volumio[4736]: info: Connection to go-librespot Websocket closed Mar 04 13:14:29 volumio systemd[1]: Started go-librespot Daemon. Mar 04 13:14:29 volumio sudo[11298]: pam_unix(sudo:session): session closed for user root Mar 04 13:14:29 volumio go-librespot[11300]: go-librespot daemon starting... Mar 04 13:14:29 volumio go-librespot[11300]: time="2025-03-04T13:14:29-03:00" level=info msg="running go-librespot 0.2.0" Mar 04 13:14:29 volumio go-librespot[11300]: time="2025-03-04T13:14:29-03:00" level=debug msg="app state loaded" Mar 04 13:14:29 volumio go-librespot[11300]: time="2025-03-04T13:14:29-03:00" level=debug msg="stored credentials not found" Mar 04 13:14:29 volumio go-librespot[11300]: time="2025-03-04T13:14:29-03:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=info msg="zeroconf server listening on port 36845" Mar 04 13:14:30 volumio volumio[4736]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 04 13:14:30 volumio volumio[4736]: SPOTIFY: BQBLZOYbWfDTKi13HQ0N6Chb-pfqcYTxuzZUFoffaxXCS5ypdqOnYRj2GZ73p28fxVoDWaNCoLy-EBoYmm4azTvqklzeLD8Hj92qX6qc4c623vDnwaoGYTZZ4jYXs5KGHzf1CGNvlIwqnNYOQuxteTlaUFLLRNiS36x3cu3zkz86r1mK67Pi3V_FQwf_TuLc67dRgSq9e4mdjy3OTAu4tCFtBYDwz6tUxsJxhcduDiMGqfq5Zl09aJMCA_zH1c-M0zzfdZysRJvs0QItsYzrXO5_miqGH8A664ZxEtq5tBQ Mar 04 13:14:30 volumio volumio[4736]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 04 13:14:30 volumio volumio[4736]: info: New Spotify access token = BQBLZOYbWfDTKi13HQ0N6Chb-pfqcYTxuzZUFoffaxXCS5ypdqOnYRj2GZ73p28fxVoDWaNCoLy-EBoYmm4azTvqklzeLD8Hj92qX6qc4c623vDnwaoGYTZZ4jYXs5KGHzf1CGNvlIwqnNYOQuxteTlaUFLLRNiS36x3cu3zkz86r1mK67Pi3V_FQwf_TuLc67dRgSq9e4mdjy3OTAu4tCFtBYDwz6tUxsJxhcduDiMGqfq5Zl09aJMCA_zH1c-M0zzfdZysRJvs0QItsYzrXO5_miqGH8A664ZxEtq5tBQ Mar 04 13:14:30 volumio volumio[4736]: info: Spotify credentials grant success - running version from March 24, 2019 Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=debug msg="obtained new client token: AADqJ0tl2iVqoR1lclAZlVY9aAN+Rv+YNjCislOeVjraLLfQFKY8HIlCqDvp4X2+KyaxH0cDjcEg8pNsfC50nevAyZN1vpwaOK9c1WJCl8/SLtF7Yvggqq1KoxeWitGFwnZtFRTa2T55oVR9XnD0m6CzN6aSEhJZ6lA6XsROh/7dagJIr5e2gikKBkF1E5faDiv36pd0o+eTAuNmynGcHUennn6v9BUS/lE5bkqY9lZtNde3l6pr0a64" Mar 04 13:14:30 volumio volumio[4736]: SPOTIFY: User informations: {"country":"BR","display_name":"Rocco","email":"parrobras@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31jnbekbdkd7zleaipqxoyu53e2i"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31jnbekbdkd7zleaipqxoyu53e2i","id":"31jnbekbdkd7zleaipqxoyu53e2i","images":[],"product":"premium","type":"user","uri":"spotify:user:31jnbekbdkd7zleaipqxoyu53e2i"} Mar 04 13:14:30 volumio volumio[4736]: info: Spotify Successfully logged in Mar 04 13:14:30 volumio volumio[4736]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 04 13:14:30 volumio volumio[4736]: info: [1741104870335] CoreMusicLibrary::Adding element Spotify Mar 04 13:14:30 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 04 13:14:30 volumio volumio[4736]: Cannot find translation for source Spotify Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=debug msg="completed keyexchange" Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=debug msg="completed challenge" Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=info msg="authenticated AP as 31jnbekbdkd7zleaipqxoyu53e2i" Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=info msg="authenticated Login5 as 31jnbekbdkd7zleaipqxoyu53e2i" Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=debug msg="stored credentials for 31jnbekbdkd7zleaipqxoyu53e2i" Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=debug msg="initializing zeroconf session, username: 31jnbekbdkd7zleaipqxoyu53e2i" Mar 04 13:14:30 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=debug msg="dealer connection opened" Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=trace msg="starting accesspoint recv loop" Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=trace msg="starting dealer recv loop" Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=trace msg="received accesspoint ping" Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 04 13:14:30 volumio go-librespot[11300]: time="2025-03-04T13:14:30-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 04 13:14:31 volumio go-librespot[11300]: time="2025-03-04T13:14:31-03:00" level=debug msg="received connection id: ZTdiOWExNTctNDBhYy00ZjlmLWFkZjMtZjg0YzVhNjVlMmIyK2RlYWxlcit0Y3A6Ly8wYWNiZmEyYS5pcC5ndWUxLnNwb3RpZnkubmV0OjU3MDArQUNGRDNENzMyMDlDREQ0QkFBRkQxMkU4N0VGRURGNjEwRTJENzBEREI1RERGODBFNjQxNEFERjU4NURENjUzNw==" Mar 04 13:14:31 volumio go-librespot[11300]: time="2025-03-04T13:14:31-03:00" level=trace msg="received accesspoint pong ack" Mar 04 13:14:31 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 04 13:14:31 volumio volumio[4736]: info: Received Get System Info Mar 04 13:14:31 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 04 13:14:31 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 04 13:14:31 volumio volumio[4736]: info: Discovery: Getting this device information Mar 04 13:14:31 volumio volumio[4736]: info: CoreCommandRouter::volumioGetState Mar 04 13:14:31 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:14:31 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 04 13:14:31 volumio go-librespot[11300]: time="2025-03-04T13:14:31-03:00" level=debug msg="put connect state because NEW_DEVICE" Mar 04 13:14:31 volumio go-librespot[11300]: time="2025-03-04T13:14:31-03:00" level=debug msg="update volume to 65535/65535" Mar 04 13:14:32 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 04 13:14:32 volumio volumio[4736]: info: Received Get System Info Mar 04 13:14:32 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 04 13:14:32 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 04 13:14:32 volumio volumio[4736]: info: Discovery: Getting this device information Mar 04 13:14:32 volumio volumio[4736]: info: CoreCommandRouter::volumioGetState Mar 04 13:14:32 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:14:32 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 04 13:14:32 volumio go-librespot[11300]: time="2025-03-04T13:14:32-03:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 04 13:14:32 volumio go-librespot[11300]: time="2025-03-04T13:14:32-03:00" level=trace msg="emitting websocket event: volume" Mar 04 13:14:32 volumio volumio[4736]: info: Initializing connection to go-librespot Websocket Mar 04 13:14:32 volumio go-librespot[11300]: time="2025-03-04T13:14:32-03:00" level=debug msg="new websocket client" Mar 04 13:14:32 volumio volumio[4736]: info: Connection to go-librespot Websocket established Mar 04 13:14:32 volumio volumio[4736]: info: go-librespot daemon successfully initialized Mar 04 13:14:35 volumio volumio[4736]: info: Getting Spotify volume Mar 04 13:14:35 volumio volumio[4736]: info: Spotify volume: 100 Mar 04 13:14:35 volumio volumio[4736]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 04 13:14:35 volumio volumio[4736]: info: CoreCommandRouter::volumioGetState Mar 04 13:14:35 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:14:35 volumio volumio[4736]: info: Initializing connection to go-librespot Websocket Mar 04 13:14:35 volumio go-librespot[11300]: time="2025-03-04T13:14:35-03:00" level=debug msg="new websocket client" Mar 04 13:14:35 volumio volumio[4736]: info: Connection to go-librespot Websocket established Mar 04 13:14:38 volumio volumio[4736]: info: Getting Spotify volume Mar 04 13:14:38 volumio volumio[4736]: info: Spotify volume: 100 Mar 04 13:14:38 volumio volumio[4736]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 04 13:14:38 volumio volumio[4736]: info: CoreCommandRouter::volumioGetState Mar 04 13:14:38 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:14:39 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Mar 04 13:14:42 volumio go-librespot[11300]: time="2025-03-04T13:14:42-03:00" level=debug msg="skipping dealer message" uri="hm://herodotus/uri/spotify:episode:77N4NRhixgAAcbYlcmUcCo/resume-point-revision/b155a1e3-45cf-4c66-9270-1258e9c9a4f6" Mar 04 13:14:42 volumio go-librespot[11300]: time="2025-03-04T13:14:42-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 287" Mar 04 13:14:46 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 04 13:14:46 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 04 13:14:46 volumio volumio[4736]: info: Discovery: Getting this device information Mar 04 13:14:46 volumio volumio[4736]: info: CoreCommandRouter::volumioGetState Mar 04 13:14:46 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:14:46 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 04 13:14:47 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 04 13:14:47 volumio volumio[4736]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Mar 04 13:14:47 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Mar 04 13:14:47 volumio volumio[4736]: info: Received Get System Version Mar 04 13:14:47 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 04 13:14:47 volumio volumio[4736]: info: Received Get System Info Mar 04 13:14:47 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 04 13:14:47 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 04 13:14:47 volumio volumio[4736]: info: Discovery: Getting this device information Mar 04 13:14:47 volumio volumio[4736]: info: CoreCommandRouter::volumioGetState Mar 04 13:14:47 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:14:47 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 04 13:14:56 volumio go-librespot[11300]: time="2025-03-04T13:14:56-03:00" level=debug msg="skipping dealer message" uri="hm://herodotus/uri/spotify:episode:77N4NRhixgAAcbYlcmUcCo/resume-point-revision/d47e5679-06a1-4b23-a292-7c2a3a2c5c67" Mar 04 13:14:56 volumio go-librespot[11300]: time="2025-03-04T13:14:56-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 287" Mar 04 13:14:58 volumio volumio[4736]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 04 13:14:58 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 04 13:14:58 volumio volumio[4736]: info: Creating Spotify config file Mar 04 13:14:58 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 04 13:14:58 volumio volumio[4736]: info: Spotify config file written Mar 04 13:14:58 volumio sudo[11361]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 04 13:14:58 volumio sudo[11361]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 04 13:14:58 volumio systemd[1]: Stopping go-librespot Daemon... Mar 04 13:14:58 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Mar 04 13:14:58 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Mar 04 13:14:58 volumio systemd[1]: Stopped go-librespot Daemon. Mar 04 13:14:58 volumio volumio[4736]: info: Connection to go-librespot Websocket closed Mar 04 13:14:58 volumio volumio[4736]: info: Connection to go-librespot Websocket closed Mar 04 13:14:58 volumio systemd[1]: Started go-librespot Daemon. Mar 04 13:14:58 volumio go-librespot[11363]: go-librespot daemon starting... Mar 04 13:14:58 volumio sudo[11361]: pam_unix(sudo:session): session closed for user root Mar 04 13:14:58 volumio go-librespot[11363]: time="2025-03-04T13:14:58-03:00" level=info msg="running go-librespot 0.2.0" Mar 04 13:14:58 volumio go-librespot[11363]: time="2025-03-04T13:14:58-03:00" level=debug msg="app state loaded" Mar 04 13:14:58 volumio go-librespot[11363]: time="2025-03-04T13:14:58-03:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 04 13:14:58 volumio go-librespot[11363]: time="2025-03-04T13:14:58-03:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 04 13:14:58 volumio go-librespot[11363]: time="2025-03-04T13:14:58-03:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 04 13:14:58 volumio go-librespot[11363]: time="2025-03-04T13:14:58-03:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 04 13:14:58 volumio go-librespot[11363]: time="2025-03-04T13:14:58-03:00" level=info msg="zeroconf server listening on port 35507" Mar 04 13:14:58 volumio go-librespot[11363]: time="2025-03-04T13:14:58-03:00" level=debug msg="obtained new client token: AAB1xIPOprOEVFHzCt7rwt6AdobMOrKWVUSGYQGI+a12rfB060bjik0ezGOfZ4VgR7CW1nIp4vq1cfsX3bU5lzaPa37DKOp6oUHE95Uh34oPsQh4/LEJSEF/UF9b2VbDYRYv/5HdwnIh9w0JjLUg4GwOYbWpawLXOZYHlwEtdZw6qmKAZWEex22Q9m1KKFWHydkJ0TwejhUaiZ80VK7Ugo2BCAVQcZfPwY6RGEMvHf8sTnyhKrZni86eLMg=" Mar 04 13:14:58 volumio go-librespot[11363]: time="2025-03-04T13:14:58-03:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Mar 04 13:14:58 volumio go-librespot[11363]: time="2025-03-04T13:14:58-03:00" level=debug msg="completed keyexchange" Mar 04 13:14:58 volumio go-librespot[11363]: time="2025-03-04T13:14:58-03:00" level=debug msg="completed challenge" Mar 04 13:14:58 volumio go-librespot[11363]: time="2025-03-04T13:14:58-03:00" level=info msg="authenticated AP as 31jnbekbdkd7zleaipqxoyu53e2i" Mar 04 13:14:59 volumio go-librespot[11363]: time="2025-03-04T13:14:59-03:00" level=info msg="authenticated Login5 as 31jnbekbdkd7zleaipqxoyu53e2i" Mar 04 13:14:59 volumio go-librespot[11363]: time="2025-03-04T13:14:59-03:00" level=debug msg="initializing zeroconf session, username: 31jnbekbdkd7zleaipqxoyu53e2i" Mar 04 13:14:59 volumio go-librespot[11363]: time="2025-03-04T13:14:59-03:00" level=debug msg="dealer connection opened" Mar 04 13:14:59 volumio go-librespot[11363]: time="2025-03-04T13:14:59-03:00" level=trace msg="starting accesspoint recv loop" Mar 04 13:14:59 volumio go-librespot[11363]: time="2025-03-04T13:14:59-03:00" level=trace msg="starting dealer recv loop" Mar 04 13:14:59 volumio go-librespot[11363]: time="2025-03-04T13:14:59-03:00" level=trace msg="received accesspoint ping" Mar 04 13:14:59 volumio go-librespot[11363]: time="2025-03-04T13:14:59-03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 04 13:14:59 volumio go-librespot[11363]: time="2025-03-04T13:14:59-03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 04 13:14:59 volumio go-librespot[11363]: time="2025-03-04T13:14:59-03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 04 13:14:59 volumio go-librespot[11363]: time="2025-03-04T13:14:59-03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 04 13:14:59 volumio go-librespot[11363]: time="2025-03-04T13:14:59-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 04 13:14:59 volumio go-librespot[11363]: time="2025-03-04T13:14:59-03:00" level=debug msg="received connection id: Mjc2NDQxYzctOTlkYS00MWY0LWFhYmYtNmY2ZDIwNDg0ZGJmK2RlYWxlcit0Y3A6Ly8wYWNiZjk0OC5pcC5ndWUxLnNwb3RpZnkubmV0OjU3MDArOEE3RDA2MkE2QTE3MDUyQzBDNDMyNzEzQUI3NkQwMzY1MjhFMEQ4ODgyRkNFOThDMTI0MURERkI5Njc0NEQ2RQ==" Mar 04 13:14:59 volumio go-librespot[11363]: time="2025-03-04T13:14:59-03:00" level=trace msg="received accesspoint pong ack" Mar 04 13:14:59 volumio go-librespot[11363]: time="2025-03-04T13:14:59-03:00" level=debug msg="put connect state because NEW_DEVICE" Mar 04 13:14:59 volumio go-librespot[11363]: time="2025-03-04T13:14:59-03:00" level=debug msg="update volume to 65535/65535" Mar 04 13:15:00 volumio volumio[4736]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 04 13:15:00 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 04 13:15:00 volumio volumio[4736]: info: Creating Spotify config file Mar 04 13:15:00 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 04 13:15:00 volumio volumio[4736]: info: Spotify config file written Mar 04 13:15:00 volumio sudo[11372]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 04 13:15:00 volumio sudo[11372]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 04 13:15:00 volumio systemd[1]: Stopping go-librespot Daemon... Mar 04 13:15:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Mar 04 13:15:00 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Mar 04 13:15:00 volumio systemd[1]: Stopped go-librespot Daemon. Mar 04 13:15:00 volumio systemd[1]: Started go-librespot Daemon. Mar 04 13:15:00 volumio go-librespot[11374]: go-librespot daemon starting... Mar 04 13:15:00 volumio sudo[11372]: pam_unix(sudo:session): session closed for user root Mar 04 13:15:00 volumio go-librespot[11374]: time="2025-03-04T13:15:00-03:00" level=info msg="running go-librespot 0.2.0" Mar 04 13:15:00 volumio go-librespot[11374]: time="2025-03-04T13:15:00-03:00" level=debug msg="app state loaded" Mar 04 13:15:00 volumio go-librespot[11374]: time="2025-03-04T13:15:00-03:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 04 13:15:00 volumio go-librespot[11374]: time="2025-03-04T13:15:00-03:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 04 13:15:00 volumio go-librespot[11374]: time="2025-03-04T13:15:00-03:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 04 13:15:00 volumio go-librespot[11374]: time="2025-03-04T13:15:00-03:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 04 13:15:00 volumio go-librespot[11374]: time="2025-03-04T13:15:00-03:00" level=info msg="zeroconf server listening on port 37609" Mar 04 13:15:00 volumio go-librespot[11374]: time="2025-03-04T13:15:00-03:00" level=debug msg="obtained new client token: AADkFU2XUsfEKn+cpMrsniMi5znOpl5C6LLAQCftK1QGwAaqsnfiRSO6JzaD6Mhx+fbkRgRkA/+3pk0WJFvhzKJ7CTem26JgJ3m4rBno8Uj+r318t2j9YEJuWfh33aByYV1zcRpgCalEX11pMzW0n87Vzt0g7AqInhpCG26XsnQxzLE04U8uFemRLNmnJExZ+GOGSDG9GGdsiE+vYnDxhJiyUNloRA8H0fqjAR5E493S7lCMeL8wqsBrd7w=" Mar 04 13:15:00 volumio go-librespot[11374]: time="2025-03-04T13:15:00-03:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Mar 04 13:15:00 volumio go-librespot[11374]: time="2025-03-04T13:15:00-03:00" level=debug msg="connected to ap-gue1.spotify.com:443" Mar 04 13:15:00 volumio go-librespot[11374]: time="2025-03-04T13:15:00-03:00" level=debug msg="completed keyexchange" Mar 04 13:15:00 volumio go-librespot[11374]: time="2025-03-04T13:15:00-03:00" level=debug msg="completed challenge" Mar 04 13:15:01 volumio volumio[4736]: info: Initializing connection to go-librespot Websocket Mar 04 13:15:01 volumio go-librespot[11374]: time="2025-03-04T13:15:01-03:00" level=debug msg="new websocket client" Mar 04 13:15:01 volumio volumio[4736]: info: Connection to go-librespot Websocket established Mar 04 13:15:01 volumio go-librespot[11374]: time="2025-03-04T13:15:01-03:00" level=info msg="authenticated AP as 31jnbekbdkd7zleaipqxoyu53e2i" Mar 04 13:15:01 volumio volumio[4736]: info: go-librespot daemon successfully initialized Mar 04 13:15:01 volumio go-librespot[11374]: time="2025-03-04T13:15:01-03:00" level=info msg="authenticated Login5 as 31jnbekbdkd7zleaipqxoyu53e2i" Mar 04 13:15:01 volumio go-librespot[11374]: time="2025-03-04T13:15:01-03:00" level=debug msg="initializing zeroconf session, username: 31jnbekbdkd7zleaipqxoyu53e2i" Mar 04 13:15:01 volumio go-librespot[11374]: time="2025-03-04T13:15:01-03:00" level=debug msg="dealer connection opened" Mar 04 13:15:01 volumio go-librespot[11374]: time="2025-03-04T13:15:01-03:00" level=trace msg="starting accesspoint recv loop" Mar 04 13:15:01 volumio go-librespot[11374]: time="2025-03-04T13:15:01-03:00" level=trace msg="starting dealer recv loop" Mar 04 13:15:01 volumio go-librespot[11374]: time="2025-03-04T13:15:01-03:00" level=trace msg="received accesspoint ping" Mar 04 13:15:01 volumio go-librespot[11374]: time="2025-03-04T13:15:01-03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 04 13:15:01 volumio go-librespot[11374]: time="2025-03-04T13:15:01-03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 04 13:15:01 volumio go-librespot[11374]: time="2025-03-04T13:15:01-03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 04 13:15:01 volumio go-librespot[11374]: time="2025-03-04T13:15:01-03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 04 13:15:01 volumio go-librespot[11374]: time="2025-03-04T13:15:01-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 04 13:15:01 volumio go-librespot[11374]: time="2025-03-04T13:15:01-03:00" level=debug msg="received connection id: YjA5NmE5NjYtYmQ4Mi00Y2YwLTg5NDEtNzA3YzZmZTM1MDJmK2RlYWxlcit0Y3A6Ly8wYWNiZjlmNS5pcC5ndWUxLnNwb3RpZnkubmV0OjU3MDArQzY4OEQyRjE4NTU3MUM4QzIxMkRCMUYzQzI5NTBBNTA5RDI4MjYzM0FEMTNCMzMxQ0U4M0ZGRDJDQjRDMTJGOA==" Mar 04 13:15:01 volumio go-librespot[11374]: time="2025-03-04T13:15:01-03:00" level=trace msg="received accesspoint pong ack" Mar 04 13:15:01 volumio go-librespot[11374]: time="2025-03-04T13:15:01-03:00" level=debug msg="put connect state because NEW_DEVICE" Mar 04 13:15:01 volumio go-librespot[11374]: time="2025-03-04T13:15:01-03:00" level=debug msg="update volume to 65535/65535" Mar 04 13:15:02 volumio go-librespot[11374]: time="2025-03-04T13:15:02-03:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 04 13:15:02 volumio go-librespot[11374]: time="2025-03-04T13:15:02-03:00" level=trace msg="emitting websocket event: volume" Mar 04 13:15:02 volumio volumio[4736]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Mar 04 13:15:02 volumio volumio[4736]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Mar 04 13:15:02 volumio volumio[4736]: info: Setting Volumio Volume from Spotify: 100 Mar 04 13:15:02 volumio volumio[4736]: info: VolumeController::SetAlsaVolume100 Mar 04 13:15:02 volumio volumio[4736]: info: CoreStateMachine::pushState Mar 04 13:15:02 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:15:02 volumio volumio[4736]: info: CoreCommandRouter::volumioPushState Mar 04 13:15:03 volumio volumio[4736]: info: go-librespot daemon successfully initialized Mar 04 13:15:04 volumio volumio[4736]: info: Getting Spotify volume Mar 04 13:15:04 volumio volumio[4736]: info: Spotify volume: 100 Mar 04 13:15:04 volumio volumio[4736]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 04 13:15:04 volumio volumio[4736]: info: CoreCommandRouter::volumioGetState Mar 04 13:15:04 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:15:04 volumio volumio[4736]: info: Initializing connection to go-librespot Websocket Mar 04 13:15:04 volumio go-librespot[11374]: time="2025-03-04T13:15:04-03:00" level=debug msg="new websocket client" Mar 04 13:15:04 volumio volumio[4736]: info: Connection to go-librespot Websocket established Mar 04 13:15:06 volumio volumio[4736]: info: Initializing connection to go-librespot Websocket Mar 04 13:15:06 volumio go-librespot[11374]: time="2025-03-04T13:15:06-03:00" level=debug msg="new websocket client" Mar 04 13:15:06 volumio volumio[4736]: info: Connection to go-librespot Websocket established Mar 04 13:15:06 volumio volumio[4736]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 04 13:15:06 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 04 13:15:06 volumio volumio[4736]: info: Creating Spotify config file Mar 04 13:15:06 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 04 13:15:06 volumio volumio[4736]: info: Spotify config file written Mar 04 13:15:06 volumio sudo[11384]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 04 13:15:06 volumio sudo[11384]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 04 13:15:06 volumio systemd[1]: Stopping go-librespot Daemon... Mar 04 13:15:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Mar 04 13:15:06 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Mar 04 13:15:06 volumio systemd[1]: Stopped go-librespot Daemon. Mar 04 13:15:06 volumio volumio[4736]: info: Connection to go-librespot Websocket closed Mar 04 13:15:06 volumio volumio[4736]: info: Connection to go-librespot Websocket closed Mar 04 13:15:06 volumio volumio[4736]: info: Connection to go-librespot Websocket closed Mar 04 13:15:06 volumio systemd[1]: Started go-librespot Daemon. Mar 04 13:15:06 volumio go-librespot[11386]: go-librespot daemon starting... Mar 04 13:15:06 volumio sudo[11384]: pam_unix(sudo:session): session closed for user root Mar 04 13:15:06 volumio go-librespot[11386]: time="2025-03-04T13:15:06-03:00" level=info msg="running go-librespot 0.2.0" Mar 04 13:15:06 volumio go-librespot[11386]: time="2025-03-04T13:15:06-03:00" level=debug msg="app state loaded" Mar 04 13:15:06 volumio go-librespot[11386]: time="2025-03-04T13:15:06-03:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=info msg="zeroconf server listening on port 37419" Mar 04 13:15:07 volumio volumio[4736]: info: Getting Spotify volume Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=debug msg="obtained new client token: AAC8nRfm+5UsYeK8Im/zLWDXr6jtT1VQ6kXQCx6xtKKoYY7Ej9XJC01a6yszkkHwlZpjWT4lxwXVm8SjSV3KtmcZe4jlvIiPzVmG/n8N0BFo7uu+Ijs1dkpQhO8B3GlFajet2LQBH5Nng+BisLbIp57NptWHSff+GkjLslb3sgYQltAU314ZFPiPn9b8i8drZM7n+edq4zXSArjKFCHCqG8n5h1jR8SnC3HzylLN2UuqXHuw5mGIlZEO" Mar 04 13:15:07 volumio volumio[4736]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 04 13:15:07 volumio volumio[4736]: info: CoreCommandRouter::volumioGetState Mar 04 13:15:07 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=debug msg="completed keyexchange" Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=debug msg="completed challenge" Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=info msg="authenticated AP as 31jnbekbdkd7zleaipqxoyu53e2i" Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=info msg="authenticated Login5 as 31jnbekbdkd7zleaipqxoyu53e2i" Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=debug msg="initializing zeroconf session, username: 31jnbekbdkd7zleaipqxoyu53e2i" Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=debug msg="dealer connection opened" Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=trace msg="starting accesspoint recv loop" Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=trace msg="starting dealer recv loop" Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=trace msg="received accesspoint ping" Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 04 13:15:07 volumio volumio[4736]: info: Spotify volume: 100 Mar 04 13:15:07 volumio go-librespot[11386]: time="2025-03-04T13:15:07-03:00" level=debug msg="received connection id: MTRjZWRjZjUtNWM2My00MWNiLWJlNjUtODczYWYxNGMzZGE1K2RlYWxlcit0Y3A6Ly8wYWNiZmIxOS5pcC5ndWUxLnNwb3RpZnkubmV0OjU3MDArODQzNUIwNTAxODJGMEU5MjFENDkxMDJGQUFFMjY0NzNGMzcwMjhGNzExNkZCNTgzMTUxNUIzQkQ2NkY5MDU5Ng==" Mar 04 13:15:08 volumio go-librespot[11386]: time="2025-03-04T13:15:08-03:00" level=trace msg="received accesspoint pong ack" Mar 04 13:15:08 volumio go-librespot[11386]: time="2025-03-04T13:15:08-03:00" level=debug msg="put connect state because NEW_DEVICE" Mar 04 13:15:08 volumio go-librespot[11386]: time="2025-03-04T13:15:08-03:00" level=debug msg="update volume to 65535/65535" Mar 04 13:15:09 volumio volumio[4736]: info: Getting Spotify volume Mar 04 13:15:09 volumio volumio[4736]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 04 13:15:09 volumio volumio[4736]: info: CoreCommandRouter::volumioGetState Mar 04 13:15:09 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:15:09 volumio go-librespot[11386]: time="2025-03-04T13:15:09-03:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 04 13:15:09 volumio go-librespot[11386]: time="2025-03-04T13:15:09-03:00" level=trace msg="emitting websocket event: volume" Mar 04 13:15:09 volumio volumio[4736]: info: Spotify volume: 100 Mar 04 13:15:09 volumio volumio[4736]: info: Initializing connection to go-librespot Websocket Mar 04 13:15:09 volumio go-librespot[11386]: time="2025-03-04T13:15:09-03:00" level=debug msg="new websocket client" Mar 04 13:15:09 volumio volumio[4736]: info: Connection to go-librespot Websocket established Mar 04 13:15:09 volumio volumio[4736]: info: go-librespot daemon successfully initialized Mar 04 13:15:10 volumio volumio[4736]: info: CoreCommandRouter::volumioGetQueue Mar 04 13:15:10 volumio volumio[4736]: info: CoreStateMachine::getQueue Mar 04 13:15:10 volumio volumio[4736]: info: CorePlayQueue::getQueue Mar 04 13:15:11 volumio go-librespot[11386]: time="2025-03-04T13:15:11-03:00" level=debug msg="skipping dealer message" uri="hm://herodotus/uri/spotify:episode:77N4NRhixgAAcbYlcmUcCo/resume-point-revision/6d02b202-3b29-4355-98a0-52c2260139e5" Mar 04 13:15:11 volumio go-librespot[11386]: time="2025-03-04T13:15:11-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 287" Mar 04 13:15:12 volumio volumio[4736]: info: Getting Spotify volume Mar 04 13:15:12 volumio volumio[4736]: info: Spotify volume: 100 Mar 04 13:15:12 volumio volumio[4736]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 04 13:15:12 volumio volumio[4736]: info: CoreCommandRouter::volumioGetState Mar 04 13:15:12 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:15:12 volumio volumio[4736]: info: Initializing connection to go-librespot Websocket Mar 04 13:15:12 volumio go-librespot[11386]: time="2025-03-04T13:15:12-03:00" level=debug msg="new websocket client" Mar 04 13:15:12 volumio volumio[4736]: info: Connection to go-librespot Websocket established Mar 04 13:15:15 volumio volumio[4736]: info: Getting Spotify volume Mar 04 13:15:15 volumio volumio[4736]: info: Spotify volume: 100 Mar 04 13:15:15 volumio volumio[4736]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 04 13:15:15 volumio volumio[4736]: info: CoreCommandRouter::volumioGetState Mar 04 13:15:15 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:15:16 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 04 13:15:16 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 04 13:15:16 volumio volumio[4736]: info: Discovery: Getting this device information Mar 04 13:15:16 volumio volumio[4736]: info: CoreCommandRouter::volumioGetState Mar 04 13:15:16 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:15:16 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 04 13:15:18 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Mar 04 13:15:18 volumio volumio[4736]: info: CURURI: music-library Mar 04 13:15:18 volumio volumio[4736]: info: Preload queue cleared Mar 04 13:15:19 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Mar 04 13:15:19 volumio volumio[4736]: info: CURURI: music-library/NAS Mar 04 13:15:19 volumio volumio[4736]: info: Preload queue cleared Mar 04 13:15:20 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Mar 04 13:15:20 volumio volumio[4736]: info: CURURI: music-library/NAS/Discografia Mar 04 13:15:20 volumio volumio[4736]: info: Preload queue cleared Mar 04 13:15:26 volumio go-librespot[11386]: time="2025-03-04T13:15:26-03:00" level=debug msg="skipping dealer message" uri="hm://herodotus/uri/spotify:episode:77N4NRhixgAAcbYlcmUcCo/resume-point-revision/cc6897b9-574b-49c2-b017-1272a56bc712" Mar 04 13:15:26 volumio go-librespot[11386]: time="2025-03-04T13:15:26-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 287" Mar 04 13:15:37 volumio go-librespot[11386]: time="2025-03-04T13:15:37-03:00" level=trace msg="sent dealer ping" Mar 04 13:15:38 volumio go-librespot[11386]: time="2025-03-04T13:15:38-03:00" level=trace msg="received dealer pong" Mar 04 13:15:42 volumio go-librespot[11386]: time="2025-03-04T13:15:42-03:00" level=debug msg="skipping dealer message" uri="hm://herodotus/uri/spotify:episode:77N4NRhixgAAcbYlcmUcCo/resume-point-revision/9dad7029-160d-41f8-aa5b-ee2a80ea50f0" Mar 04 13:15:42 volumio go-librespot[11386]: time="2025-03-04T13:15:42-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 287" Mar 04 13:15:44 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Mar 04 13:15:44 volumio volumio[4736]: info: CURURI: music-library/NAS/DSD Mar 04 13:15:44 volumio volumio[4736]: info: Preload queue cleared Mar 04 13:15:46 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 04 13:15:46 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 04 13:15:46 volumio volumio[4736]: info: Discovery: Getting this device information Mar 04 13:15:46 volumio volumio[4736]: info: CoreCommandRouter::volumioGetState Mar 04 13:15:46 volumio volumio[4736]: info: CorePlayQueue::getTrack 0 Mar 04 13:15:46 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 04 13:15:51 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Mar 04 13:15:51 volumio volumio[4736]: info: Preload queue cleared Mar 04 13:15:52 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Mar 04 13:15:52 volumio volumio[4736]: info: Preload queue cleared Mar 04 13:15:55 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Mar 04 13:15:55 volumio volumio[4736]: info: Preload queue cleared Mar 04 13:15:56 volumio go-librespot[11386]: time="2025-03-04T13:15:56-03:00" level=debug msg="skipping dealer message" uri="hm://herodotus/uri/spotify:episode:77N4NRhixgAAcbYlcmUcCo/resume-point-revision/0b241e0f-4e99-4e40-8552-39962848773e" Mar 04 13:15:56 volumio go-librespot[11386]: time="2025-03-04T13:15:56-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 287" Mar 04 13:15:58 volumio volumio[4736]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Mar 04 13:15:58 volumio volumio[4736]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 04 13:15:58 volumio volumio[4736]: TypeError: Cannot read property 'length' of undefined Mar 04 13:15:58 volumio volumio[4736]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Mar 04 13:15:58 volumio volumio[4736]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Mar 04 13:15:58 volumio volumio[4736]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Mar 04 13:15:58 volumio volumio[4736]: at Parser.emit (events.js:315:20) Mar 04 13:15:58 volumio volumio[4736]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Mar 04 13:15:58 volumio volumio[4736]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Mar 04 13:15:58 volumio volumio[4736]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Mar 04 13:15:58 volumio volumio[4736]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Mar 04 13:15:58 volumio volumio[4736]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Mar 04 13:15:58 volumio volumio[4736]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Mar 04 13:15:58 volumio volumio[4736]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Mar 04 13:15:58 volumio volumio[4736]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Mar 04 13:15:58 volumio volumio[4736]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Mar 04 13:15:58 volumio volumio[4736]: at IncomingMessage.emit (events.js:327:22) Mar 04 13:15:58 volumio volumio[4736]: at endReadableNT (internal/streams/readable.js:1327:12) Mar 04 13:15:58 volumio volumio[4736]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Mar 04 13:15:58 volumio volumio[4736]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 04 13:15:59 volumio sudo[11548]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-04 13:14 Mar 04 13:15:59 volumio sudo[11548]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="f6610a1100d2380eef33bd3004af43153c786f96" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1c0e5daee99fe3a72cc38b0d1fe6cd78d7f001fe" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 16 Dec 2024 09:30:04 AM CET" VOLUMIO_VERSION="3.785" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fe0ac4b79aed19ccde4b5bd83d468193"