May 29 08:18:52 volumio volumio[1236]: info: Received OAUTH Data May 29 08:18:52 volumio volumio[1236]: info: Executing Spotify Oauth Login May 29 08:18:52 volumio volumio[1236]: info: Saving Spotify Refresh Token May 29 08:18:52 volumio sudo[5946]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 29 08:18:52 volumio sudo[5946]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:18:52 volumio sudo[5948]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 29 08:18:52 volumio sudo[5946]: pam_unix(sudo:session): session closed for user root May 29 08:18:52 volumio sudo[5948]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:18:52 volumio sudo[5948]: pam_unix(sudo:session): session closed for user root May 29 08:18:52 volumio volumio[1236]: verbose: New Socket.io Connection to 192.168.0.193 from 192.168.0.183 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/137.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 May 29 08:18:52 volumio volumio[1236]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 29 08:18:52 volumio volumio[1236]: SPOTIFY: BQBBFdNGNxOUca8Yw2nNBZxeUBJDkDGwzkRbAkR_6xGnjhDzMMpBUtZKGHo5w0X8Uka-XmwQKU4JR50g3u9qoErNuGo5RscPghpTTISwJzCVt4Vak0tiOzaxpBjlfF3lwvjs1UDosexKytAUZH7wicC-9WGCIDpTAyhE-bnTf39vRHVqKWA1KgOwZ3RSQdswAiI8uPEE_GaNXUcIAsecNcfO2KQ4q1ghfGDcZBwQ1BanFdqePP83XKoaNuEm_8vJrfMZN8yVYp8Qh5DsIhuFKfeQrLiYCAR080Ni-AQJx2y6SCk May 29 08:18:52 volumio volumio[1236]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 29 08:18:52 volumio volumio[1236]: info: New Spotify access token = BQBBFdNGNxOUca8Yw2nNBZxeUBJDkDGwzkRbAkR_6xGnjhDzMMpBUtZKGHo5w0X8Uka-XmwQKU4JR50g3u9qoErNuGo5RscPghpTTISwJzCVt4Vak0tiOzaxpBjlfF3lwvjs1UDosexKytAUZH7wicC-9WGCIDpTAyhE-bnTf39vRHVqKWA1KgOwZ3RSQdswAiI8uPEE_GaNXUcIAsecNcfO2KQ4q1ghfGDcZBwQ1BanFdqePP83XKoaNuEm_8vJrfMZN8yVYp8Qh5DsIhuFKfeQrLiYCAR080Ni-AQJx2y6SCk May 29 08:18:52 volumio volumio[1236]: info: Spotify credentials grant success - running version from March 24, 2019 May 29 08:18:52 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 29 08:18:52 volumio volumio[1236]: info: CoreCommandRouter::volumioGetVisibleSources May 29 08:18:52 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 29 08:18:52 volumio volumio[1236]: info: CoreCommandRouter::volumioGetState May 29 08:18:52 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:18:52 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 29 08:18:52 volumio volumio[1236]: info: CoreCommandRouter::getUIConfigOnPlugin May 29 08:18:52 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 29 08:18:52 volumio volumio[1236]: info: Received Get System Info May 29 08:18:52 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 08:18:52 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 08:18:52 volumio volumio[1236]: info: Discovery: Getting this device information May 29 08:18:52 volumio volumio[1236]: info: CoreCommandRouter::volumioGetState May 29 08:18:52 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:18:52 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 08:18:52 volumio volumio[1236]: info: CoreCommandRouter::volumioGetState May 29 08:18:52 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:18:52 volumio volumio[1236]: info: Listing playlists May 29 08:18:52 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings May 29 08:18:52 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 29 08:18:52 volumio volumio[1236]: SPOTIFY: User informations: {"country":"UA","display_name":"Igor","email":"ihhorm@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/pb5pp9zr5gss9vfrrdysusbut"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/pb5pp9zr5gss9vfrrdysusbut","id":"pb5pp9zr5gss9vfrrdysusbut","images":[],"product":"premium","type":"user","uri":"spotify:user:pb5pp9zr5gss9vfrrdysusbut"} May 29 08:18:52 volumio volumio[1236]: info: Creating Spotify config file May 29 08:18:52 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 08:18:52 volumio volumio[1236]: info: Spotify config file written May 29 08:18:52 volumio sudo[5953]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 29 08:18:52 volumio sudo[5953]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:18:52 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 29 08:18:52 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... May 29 08:18:52 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 29 08:18:52 volumio systemd[1]: go-librespot-daemon.service: Killing process 5628 (go-librespot) with signal SIGKILL. May 29 08:18:52 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 29 08:18:52 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 29 08:18:52 volumio volumio[1236]: info: Connection to go-librespot Websocket closed May 29 08:18:52 volumio volumio[1236]: info: Connection to go-librespot Websocket closed May 29 08:18:52 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 29 08:18:52 volumio sudo[5953]: pam_unix(sudo:session): session closed for user root May 29 08:18:52 volumio go-librespot[5958]: go-librespot daemon starting... May 29 08:18:52 volumio dbus-daemon[867]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.45' (uid=0 pid=5956 comm="timedatectl show --property=NTPSynchronized --valu") May 29 08:18:52 volumio go-librespot[5959]: time="2025-05-29T08:18:52+03:00" level=info msg="running go-librespot 0.2.0" May 29 08:18:52 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service... May 29 08:18:52 volumio go-librespot[5959]: time="2025-05-29T08:18:52+03:00" level=debug msg="app state loaded" May 29 08:18:52 volumio go-librespot[5959]: time="2025-05-29T08:18:52+03:00" level=debug msg="stored credentials not found" May 29 08:18:52 volumio go-librespot[5959]: time="2025-05-29T08:18:52+03:00" level=info msg="api server listening on 127.0.0.1:9879" May 29 08:18:52 volumio dbus-daemon[867]: [system] Successfully activated service 'org.freedesktop.timedate1' May 29 08:18:52 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service. May 29 08:18:52 volumio setdatetime-helper.sh[5955]: Time is not synchronized. Attempting to sync... May 29 08:18:52 volumio go-librespot[5959]: time="2025-05-29T08:18:52+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" May 29 08:18:52 volumio go-librespot[5959]: time="2025-05-29T08:18:52+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 29 08:18:52 volumio go-librespot[5959]: time="2025-05-29T08:18:52+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 29 08:18:52 volumio go-librespot[5959]: time="2025-05-29T08:18:52+03:00" level=info msg="zeroconf server listening on port 41285" May 29 08:18:52 volumio sudo[5973]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Thu, 29 May 2025 05:18:53 GMT#015' May 29 08:18:52 volumio sudo[5973]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) May 29 08:18:53 volumio setdatetime-helper.sh[5974]: Thu May 29 08:18:53 EEST 2025 May 29 08:18:53 volumio sudo[5973]: pam_unix(sudo:session): session closed for user root May 29 08:18:53 volumio setdatetime-helper.sh[5955]: Time synchronized successfully. May 29 08:18:53 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. May 29 08:18:53 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. May 29 08:18:53 volumio volumio[1236]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 29 08:18:53 volumio volumio[1236]: SPOTIFY: BQCOp55EBR8wjNisN-hrHNWbFLpMqCzGBbGYmMkMKVeDZeW8j9NHDJFKeKeS6_QLPLS_mMy-C30QCwQWPmTqmbBILCYyxqWK73SANmhWf5maX0QMTqrFC01noSHMLwyxlTXTMLNgZXwDSBpHDYdnSmautOs4qdmnqSxIJ8eIL_P1cHoKsRHISlyINt-vNkA5EVwsZwqtYsYZXi-v6B1BmKC0Q8uLWFdEWCSINDP93TOQRnT06CZZOE72_3_ta9WzrH6MObg1GoH0g1g0QPaFRB6CDyO6fgNDfDuc9fKGxsiCj0M May 29 08:18:53 volumio volumio[1236]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 29 08:18:53 volumio volumio[1236]: info: New Spotify access token = BQCOp55EBR8wjNisN-hrHNWbFLpMqCzGBbGYmMkMKVeDZeW8j9NHDJFKeKeS6_QLPLS_mMy-C30QCwQWPmTqmbBILCYyxqWK73SANmhWf5maX0QMTqrFC01noSHMLwyxlTXTMLNgZXwDSBpHDYdnSmautOs4qdmnqSxIJ8eIL_P1cHoKsRHISlyINt-vNkA5EVwsZwqtYsYZXi-v6B1BmKC0Q8uLWFdEWCSINDP93TOQRnT06CZZOE72_3_ta9WzrH6MObg1GoH0g1g0QPaFRB6CDyO6fgNDfDuc9fKGxsiCj0M May 29 08:18:53 volumio volumio[1236]: info: Spotify credentials grant success - running version from March 24, 2019 May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=debug msg="obtained new client token: AABWJfPMSOKC0V+nhra7+9+kUE3gWpTWiPWoT0ci/U/5cuB6/RcQIrQCsBbWhvWemt0z0S9nUZ+c064Qbq2mheLH4l7yDYqkhVyYLhz1Muo0dtOR82QAPE/1t5XdycmrTPku5Vef618acrMPAemiNdObcoW129BHHKUOJeWVx0UX+fdTW3nUWDhY04L3qsHAMSUS+bC1Hs231oBwPTximugagC+tdr/BXH/klSxvkh9Kc5lEeuBpg1Y=" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" May 29 08:18:53 volumio volumio[1236]: SPOTIFY: User informations: {"country":"UA","display_name":"Igor","email":"ihhorm@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/pb5pp9zr5gss9vfrrdysusbut"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/pb5pp9zr5gss9vfrrdysusbut","id":"pb5pp9zr5gss9vfrrdysusbut","images":[],"product":"premium","type":"user","uri":"spotify:user:pb5pp9zr5gss9vfrrdysusbut"} May 29 08:18:53 volumio volumio[1236]: info: Spotify Successfully logged in May 29 08:18:53 volumio volumio[1236]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 29 08:18:53 volumio volumio[1236]: info: [1748495933183] CoreMusicLibrary::Adding element Spotify May 29 08:18:53 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 29 08:18:53 volumio volumio[1236]: Cannot find translation for source YouTube2 May 29 08:18:53 volumio volumio[1236]: Cannot find translation for source YouTube Music May 29 08:18:53 volumio volumio[1236]: Cannot find translation for source Spotify May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=debug msg="connected to ap-gew1.spotify.com:443" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=debug msg="completed keyexchange" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=debug msg="completed challenge" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=info msg="authenticated AP as pb5pp9zr5gss9vfrrdysusbut" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=info msg="authenticated Login5 as pb5pp9zr5gss9vfrrdysusbut" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=debug msg="stored credentials for pb5pp9zr5gss9vfrrdysusbut" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=debug msg="initializing zeroconf session, username: pb5pp9zr5gss9vfrrdysusbut" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=debug msg="dealer connection opened" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=trace msg="starting accesspoint recv loop" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=trace msg="starting dealer recv loop" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=trace msg="received accesspoint ping" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=debug msg="received connection id: MjZjNzYwOWItNDczZS00YTNmLTkxMTktNjFiNDgzNjU0YTEwK2RlYWxlcit0Y3A6Ly8wYWNhNDA0NC5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArNTg2ODRDMkYzODQ1QUVBNEJCRTUyQUUxMjQ4QzYyRDk3QThGQjU0MEM2QjU2QTA1OTMyMkZCQjc3ODAyOEYwNw==" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=trace msg="received accesspoint pong ack" May 29 08:18:53 volumio go-librespot[5959]: time="2025-05-29T08:18:53+03:00" level=debug msg="put connect state because NEW_DEVICE" May 29 08:18:54 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard May 29 08:18:54 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 29 08:18:54 volumio volumio[1236]: info: Received Get System Info May 29 08:18:54 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 08:18:54 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 08:18:54 volumio volumio[1236]: info: Discovery: Getting this device information May 29 08:18:54 volumio volumio[1236]: info: CoreCommandRouter::volumioGetState May 29 08:18:54 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:18:54 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 08:18:55 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 29 08:18:55 volumio volumio[1236]: info: Received Get System Info May 29 08:18:55 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 08:18:55 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 08:18:55 volumio volumio[1236]: info: Discovery: Getting this device information May 29 08:18:55 volumio volumio[1236]: info: CoreCommandRouter::volumioGetState May 29 08:18:55 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:18:55 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 08:18:55 volumio volumio[1236]: info: Initializing connection to go-librespot Websocket May 29 08:18:55 volumio go-librespot[5959]: time="2025-05-29T08:18:55+03:00" level=debug msg="new websocket client" May 29 08:18:55 volumio volumio[1236]: info: Connection to go-librespot Websocket established May 29 08:18:55 volumio volumio[1236]: info: go-librespot daemon successfully initialized May 29 08:18:58 volumio volumio[1236]: info: Getting Spotify volume May 29 08:18:58 volumio volumio[1236]: info: Initializing connection to go-librespot Websocket May 29 08:18:58 volumio volumio[1236]: info: Spotify volume: 100 May 29 08:18:58 volumio go-librespot[5959]: time="2025-05-29T08:18:58+03:00" level=debug msg="new websocket client" May 29 08:18:58 volumio volumio[1236]: info: Connection to go-librespot Websocket established May 29 08:18:58 volumio volumio[1236]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 May 29 08:18:58 volumio volumio[1236]: info: CoreCommandRouter::volumioGetState May 29 08:18:58 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:18:58 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:01 volumio volumio[1236]: info: Getting Spotify volume May 29 08:19:01 volumio volumio[1236]: info: Spotify volume: 100 May 29 08:19:01 volumio volumio[1236]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 May 29 08:19:01 volumio volumio[1236]: info: CoreCommandRouter::volumioGetState May 29 08:19:01 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:19:01 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:02 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 29 08:19:03 volumio volumio[1236]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] May 29 08:19:03 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings May 29 08:19:03 volumio volumio[1236]: info: Creating Spotify config file May 29 08:19:03 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 08:19:03 volumio volumio[1236]: info: Spotify config file written May 29 08:19:03 volumio sudo[6013]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 29 08:19:03 volumio sudo[6013]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:19:03 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 29 08:19:03 volumio systemd[1]: go-librespot-daemon.service: Killing process 5963 (go-librespot) with signal SIGKILL. May 29 08:19:03 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 29 08:19:03 volumio volumio[1236]: info: Connection to go-librespot Websocket closed May 29 08:19:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 29 08:19:03 volumio volumio[1236]: info: Connection to go-librespot Websocket closed May 29 08:19:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 29 08:19:03 volumio sudo[6013]: pam_unix(sudo:session): session closed for user root May 29 08:19:03 volumio go-librespot[6015]: go-librespot daemon starting... May 29 08:19:03 volumio go-librespot[6016]: time="2025-05-29T08:19:03+03:00" level=info msg="running go-librespot 0.2.0" May 29 08:19:03 volumio go-librespot[6016]: time="2025-05-29T08:19:03+03:00" level=debug msg="app state loaded" May 29 08:19:03 volumio go-librespot[6016]: time="2025-05-29T08:19:03+03:00" level=info msg="api server listening on 127.0.0.1:9879" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=info msg="zeroconf server listening on port 36273" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=debug msg="obtained new client token: AADeGUaLSrh0exfOVpfVjJ5RrPUmibpm5xltn45IaypqTQqbCoj71TLyV94jqO414c9N/Hmc2bNMrXlkQkZKEaSjnLEojm6NRRICOUHEE7Yym/LN3YJ3eoe7SVizj2QsnGoHfxz71UUlx2GLzNtQPFI2ZvbccsLxNYQkXixCM9I+x/LVyRREjfm047BvNXaiGqgTS52Ffx5/Paj/yUlNoEUJVYJsma0exwWqvirieLaJqyCtXccK1V4=" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=debug msg="completed keyexchange" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=debug msg="completed challenge" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=info msg="authenticated AP as pb5pp9zr5gss9vfrrdysusbut" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=info msg="authenticated Login5 as pb5pp9zr5gss9vfrrdysusbut" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=debug msg="initializing zeroconf session, username: pb5pp9zr5gss9vfrrdysusbut" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=debug msg="dealer connection opened" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=trace msg="starting accesspoint recv loop" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=trace msg="starting dealer recv loop" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=trace msg="received accesspoint ping" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=debug msg="received connection id: ZDQ2MjUwMjgtZWNjZi00NzZlLTkyOTUtMGI1N2ZmOTI2Y2QzK2RlYWxlcit0Y3A6Ly8wYWNhNDBmNy5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMjFCNEFBOTQzMUYzQTc2NjYxMDAzOEE1QUY4QUJCRjJCQ0YzQTJCNTAwMzlBRDMyOUY3QjQxODlBRUI0QUEwRQ==" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=trace msg="received accesspoint pong ack" May 29 08:19:04 volumio go-librespot[6016]: time="2025-05-29T08:19:04+03:00" level=debug msg="put connect state because NEW_DEVICE" May 29 08:19:06 volumio volumio[1236]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] May 29 08:19:06 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings May 29 08:19:06 volumio volumio[1236]: info: Creating Spotify config file May 29 08:19:06 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 08:19:06 volumio volumio[1236]: info: Spotify config file written May 29 08:19:06 volumio sudo[6045]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 29 08:19:06 volumio sudo[6045]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:19:06 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 29 08:19:06 volumio systemd[1]: go-librespot-daemon.service: Killing process 6023 (go-librespot) with signal SIGKILL. May 29 08:19:06 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 29 08:19:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 29 08:19:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 29 08:19:06 volumio sudo[6045]: pam_unix(sudo:session): session closed for user root May 29 08:19:06 volumio go-librespot[6047]: go-librespot daemon starting... May 29 08:19:06 volumio go-librespot[6048]: time="2025-05-29T08:19:06+03:00" level=info msg="running go-librespot 0.2.0" May 29 08:19:06 volumio go-librespot[6048]: time="2025-05-29T08:19:06+03:00" level=debug msg="app state loaded" May 29 08:19:06 volumio go-librespot[6048]: time="2025-05-29T08:19:06+03:00" level=info msg="api server listening on 127.0.0.1:9879" May 29 08:19:06 volumio volumio[1236]: info: Initializing connection to go-librespot Websocket May 29 08:19:06 volumio go-librespot[6048]: time="2025-05-29T08:19:06+03:00" level=debug msg="new websocket client" May 29 08:19:06 volumio volumio[1236]: info: Connection to go-librespot Websocket established May 29 08:19:06 volumio go-librespot[6048]: time="2025-05-29T08:19:06+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" May 29 08:19:06 volumio go-librespot[6048]: time="2025-05-29T08:19:06+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 29 08:19:06 volumio go-librespot[6048]: time="2025-05-29T08:19:06+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 29 08:19:06 volumio go-librespot[6048]: time="2025-05-29T08:19:06+03:00" level=info msg="zeroconf server listening on port 32911" May 29 08:19:06 volumio volumio[1236]: info: go-librespot daemon successfully initialized May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=debug msg="obtained new client token: AADJsDbhQnz/F8e/p0B+TZMes8eGeiCiN2ieDmt6MfLcKSConTbr7deDni0w3OJ3uPdqi7VyFhalVZXCER4dok5szufI5jXb5NL6rZG1Y+nJl1LwKbvMDX7IJgAdvwhysUqyfo2BDnPtg/Wdt1hZNlaWZ7OqE5/9Ptih78REw4bFOT5o6n7h1lgH5kr3RyN36EEeTGBMooT6xVZRwyS1ndpYN+dB5gNUbgP/lys9GGzt71zhHi+xlXY=" May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=debug msg="completed keyexchange" May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=debug msg="completed challenge" May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=info msg="authenticated AP as pb5pp9zr5gss9vfrrdysusbut" May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=info msg="authenticated Login5 as pb5pp9zr5gss9vfrrdysusbut" May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=debug msg="initializing zeroconf session, username: pb5pp9zr5gss9vfrrdysusbut" May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=debug msg="dealer connection opened" May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=trace msg="starting accesspoint recv loop" May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=trace msg="starting dealer recv loop" May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=trace msg="received accesspoint ping" May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=debug msg="received connection id: YTRiNjYzYTEtZDlmZS00ZDk5LWE0MWQtNzg4NTRiMjYyMDkyK2RlYWxlcit0Y3A6Ly8wYWNhNDI1YS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMzgxRUJGMjJBRkNBNDFBNjc0NDNDQjUxRTQ1MEM1MjdGMUY3QkI4RkYyMTE3MTVFM0UwODlEN0UyRjU1QTg2Qg==" May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=trace msg="received accesspoint pong ack" May 29 08:19:07 volumio go-librespot[6048]: time="2025-05-29T08:19:07+03:00" level=debug msg="put connect state because NEW_DEVICE" May 29 08:19:07 volumio volumio[1236]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] May 29 08:19:07 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings May 29 08:19:07 volumio volumio[1236]: info: Creating Spotify config file May 29 08:19:07 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 08:19:07 volumio volumio[1236]: info: Spotify config file written May 29 08:19:07 volumio sudo[6059]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 29 08:19:07 volumio sudo[6059]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:19:07 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 29 08:19:07 volumio systemd[1]: go-librespot-daemon.service: Killing process 6055 (go-librespot) with signal SIGKILL. May 29 08:19:07 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 29 08:19:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 29 08:19:07 volumio volumio[1236]: info: Connection to go-librespot Websocket closed May 29 08:19:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 29 08:19:07 volumio go-librespot[6061]: go-librespot daemon starting... May 29 08:19:07 volumio sudo[6059]: pam_unix(sudo:session): session closed for user root May 29 08:19:07 volumio go-librespot[6062]: time="2025-05-29T08:19:07+03:00" level=info msg="running go-librespot 0.2.0" May 29 08:19:07 volumio go-librespot[6062]: time="2025-05-29T08:19:07+03:00" level=debug msg="app state loaded" May 29 08:19:07 volumio go-librespot[6062]: time="2025-05-29T08:19:07+03:00" level=info msg="api server listening on 127.0.0.1:9879" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=info msg="zeroconf server listening on port 35681" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=debug msg="obtained new client token: AAAATPA3sLc3zDislxDSpnDtr3Cz8TYRSyf0aQu763KY/Y8L+6Il4hv0/RL5kx9VevePTWVhY7ANtiPanzy3hy6iL5yP14Hbysxph7Cc5ONlKACz0H+65kmIo0zF67lXVHhlx029oh5K7sngOWP0RbHW99hYmdyiTc2NdAXUi9JvjOvqLelYm97ccDtHc0W7MkuPEniA6Ifi+o2HSnYuzYRDkJ/nw30/QsjIpOTn6HcSCwL63J5HY7s=" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=debug msg="completed keyexchange" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=debug msg="completed challenge" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=info msg="authenticated AP as pb5pp9zr5gss9vfrrdysusbut" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=info msg="authenticated Login5 as pb5pp9zr5gss9vfrrdysusbut" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=debug msg="initializing zeroconf session, username: pb5pp9zr5gss9vfrrdysusbut" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=debug msg="dealer connection opened" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=trace msg="starting accesspoint recv loop" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=trace msg="starting dealer recv loop" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=trace msg="received accesspoint ping" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=debug msg="received connection id: NjA2ZDkyNzAtZGRmOS00ZWEzLTk3ZmYtNmZhNGMzZTE1Yjg3K2RlYWxlcit0Y3A6Ly8wYWNhNDI1Zi5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArNkQ1MEUxNDA0QTFGNTdDODFGQTA1ODRCODFGNUI0M0UwNUQwRDc1MzNBQ0JGMTlERDlERDU4MDU2NTI2MDQ5RA==" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=trace msg="received accesspoint pong ack" May 29 08:19:08 volumio go-librespot[6062]: time="2025-05-29T08:19:08+03:00" level=debug msg="put connect state because NEW_DEVICE" May 29 08:19:09 volumio volumio[1236]: info: go-librespot daemon successfully initialized May 29 08:19:09 volumio volumio[1236]: info: Getting Spotify volume May 29 08:19:09 volumio volumio[1236]: info: Spotify volume: 100 May 29 08:19:09 volumio volumio[1236]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 May 29 08:19:09 volumio volumio[1236]: info: CoreCommandRouter::volumioGetState May 29 08:19:09 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:19:09 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:09 volumio volumio[1236]: info: Initializing connection to go-librespot Websocket May 29 08:19:09 volumio go-librespot[6062]: time="2025-05-29T08:19:09+03:00" level=debug msg="new websocket client" May 29 08:19:09 volumio volumio[1236]: info: Connection to go-librespot Websocket established May 29 08:19:10 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 29 08:19:10 volumio volumio[1236]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined May 29 08:19:10 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates May 29 08:19:10 volumio volumio[1236]: info: Received Get System Version May 29 08:19:10 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 29 08:19:10 volumio volumio[1236]: info: Received Get System Info May 29 08:19:10 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 08:19:10 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 08:19:10 volumio volumio[1236]: info: Discovery: Getting this device information May 29 08:19:10 volumio volumio[1236]: info: CoreCommandRouter::volumioGetState May 29 08:19:10 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:19:10 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 08:19:10 volumio volumio[1236]: info: Initializing connection to go-librespot Websocket May 29 08:19:10 volumio go-librespot[6062]: time="2025-05-29T08:19:10+03:00" level=debug msg="new websocket client" May 29 08:19:10 volumio volumio[1236]: info: Connection to go-librespot Websocket established May 29 08:19:10 volumio volumio[1236]: info: go-librespot daemon successfully initialized May 29 08:19:10 volumio volumio[1236]: info: CoreCommandRouter::volumioGetState May 29 08:19:10 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:19:11 volumio volumio[1236]: info: CoreCommandRouter::volumioGetQueue May 29 08:19:11 volumio volumio[1236]: info: CoreStateMachine::getQueue May 29 08:19:11 volumio volumio[1236]: info: CorePlayQueue::getQueue May 29 08:19:12 volumio volumio[1236]: info: Initializing connection to go-librespot Websocket May 29 08:19:12 volumio go-librespot[6062]: time="2025-05-29T08:19:12+03:00" level=debug msg="new websocket client" May 29 08:19:12 volumio volumio[1236]: info: Connection to go-librespot Websocket established May 29 08:19:12 volumio volumio[1236]: info: Getting Spotify volume May 29 08:19:12 volumio volumio[1236]: info: Spotify volume: 100 May 29 08:19:12 volumio volumio[1236]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 May 29 08:19:12 volumio volumio[1236]: info: CoreCommandRouter::volumioGetState May 29 08:19:12 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:19:12 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:13 volumio volumio[1236]: info: Getting Spotify volume May 29 08:19:13 volumio volumio[1236]: info: Spotify volume: 100 May 29 08:19:13 volumio volumio[1236]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 May 29 08:19:13 volumio volumio[1236]: info: Initializing connection to go-librespot Websocket May 29 08:19:13 volumio volumio[1236]: info: CoreCommandRouter::volumioGetState May 29 08:19:13 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:19:13 volumio go-librespot[6062]: time="2025-05-29T08:19:13+03:00" level=debug msg="new websocket client" May 29 08:19:13 volumio volumio[1236]: info: Connection to go-librespot Websocket established May 29 08:19:13 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:15 volumio volumio[1236]: info: CoreCommandRouter::volumioGetState May 29 08:19:15 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:19:15 volumio volumio[1236]: info: Getting Spotify volume May 29 08:19:15 volumio volumio[1236]: info: Spotify volume: 100 May 29 08:19:15 volumio volumio[1236]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 May 29 08:19:15 volumio volumio[1236]: info: CoreCommandRouter::volumioGetState May 29 08:19:15 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:19:15 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:16 volumio volumio[1236]: info: Getting Spotify volume May 29 08:19:16 volumio volumio[1236]: info: Spotify volume: 100 May 29 08:19:16 volumio volumio[1236]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 May 29 08:19:16 volumio volumio[1236]: info: CoreCommandRouter::volumioGetState May 29 08:19:16 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:19:16 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:22 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 29 08:19:22 volumio volumio[1236]: info: In handleBrowseUri, curUri=spotify May 29 08:19:22 volumio volumio[1236]: info: Preload queue cleared May 29 08:19:22 volumio volumio[1236]: info: Preload queue cleared May 29 08:19:22 volumio volumio[1236]: info: Preload queue cleared May 29 08:19:22 volumio volumio[1236]: info: Preload queue cleared May 29 08:19:22 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. May 29 08:19:30 volumio volumio[1236]: info: Preload queue cleared May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::volumioReplaceandPlayItems May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::ClearQueue May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::stop May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::stPlaybackTimer May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::updateTrackBlock May 29 08:19:30 volumio volumio[1236]: info: CorePlayQueue::getTrackBlock May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::pushState May 29 08:19:30 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::volumioPushState May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::serviceStop May 29 08:19:30 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::serviceStop May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::setConsumeUpdateService mpd May 29 08:19:30 volumio volumio[1236]: info: ControllerMpd::stop May 29 08:19:30 volumio volumio[1236]: verbose: ControllerMpd::sendMpdCommand stop May 29 08:19:30 volumio volumio[1236]: info: CorePlayQueue::clearPlayQueue May 29 08:19:30 volumio volumio[1236]: info: CorePlayQueue::saveQueue May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::volumioPushQueue May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::addQueueItems May 29 08:19:30 volumio volumio[1236]: info: CorePlayQueue::addQueueItems May 29 08:19:30 volumio volumio[1236]: info: Preload queue cleared May 29 08:19:30 volumio volumio[1236]: info: Adding Item to queue: spotify:playlist:37i9dQZF1DX2X2YHi92QqA May 29 08:19:30 volumio volumio[1236]: info: Exploding uri spotify:playlist:37i9dQZF1DX2X2YHi92QqA in service spop May 29 08:19:30 volumio volumio[1236]: SPOTIFY: EXPLODING URI:spotify:playlist:37i9dQZF1DX2X2YHi92QqA May 29 08:19:30 volumio volumio[1236]: info: PeppyMeterBasic ---peppymeterbasic status stop May 29 08:19:30 volumio volumio[1236]: info: May 29 08:19:30 volumio volumio[1236]: ---------------------------- MPD announces state update: player May 29 08:19:30 volumio volumio[1236]: info: sendMpdCommand stop took 20 milliseconds May 29 08:19:30 volumio volumio[1236]: info: ControllerMpd::getState May 29 08:19:30 volumio volumio[1236]: verbose: ControllerMpd::sendMpdCommand status May 29 08:19:30 volumio volumio[1236]: info: May 29 08:19:30 volumio volumio[1236]: ---------------------------- MPD announces state update: player May 29 08:19:30 volumio volumio[1236]: info: ControllerMpd::getState May 29 08:19:30 volumio volumio[1236]: verbose: ControllerMpd::sendMpdCommand status May 29 08:19:30 volumio volumio[1236]: info: May 29 08:19:30 volumio volumio[1236]: ---------------------------- MPD announces state update: player May 29 08:19:30 volumio volumio[1236]: info: ControllerMpd::getState May 29 08:19:30 volumio volumio[1236]: verbose: ControllerMpd::sendMpdCommand status May 29 08:19:30 volumio volumio[1236]: info: May 29 08:19:30 volumio volumio[1236]: ---------------------------- MPD announces state update: player May 29 08:19:30 volumio volumio[1236]: info: ControllerMpd::getState May 29 08:19:30 volumio volumio[1236]: verbose: ControllerMpd::sendMpdCommand status May 29 08:19:30 volumio volumio[1236]: info: sendMpdCommand status took 2 milliseconds May 29 08:19:30 volumio sudo[6148]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service May 29 08:19:30 volumio sudo[6148]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:19:30 volumio volumio[1236]: info: sendMpdCommand status took 3 milliseconds May 29 08:19:30 volumio volumio[1236]: info: sendMpdCommand status took 2 milliseconds May 29 08:19:30 volumio volumio[1236]: info: sendMpdCommand status took 2 milliseconds May 29 08:19:30 volumio volumio[1236]: verbose: ControllerMpd::parseState May 29 08:19:30 volumio volumio[1236]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 29 08:19:30 volumio volumio[1236]: verbose: ControllerMpd::parseState May 29 08:19:30 volumio volumio[1236]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 29 08:19:30 volumio volumio[1236]: verbose: ControllerMpd::parseState May 29 08:19:30 volumio volumio[1236]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 29 08:19:30 volumio volumio[1236]: verbose: ControllerMpd::parseState May 29 08:19:30 volumio volumio[1236]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 29 08:19:30 volumio volumio[1236]: info: sendMpdCommand playlistinfo took 2 milliseconds May 29 08:19:30 volumio volumio[1236]: info: sendMpdCommand playlistinfo took 2 milliseconds May 29 08:19:30 volumio volumio[1236]: info: sendMpdCommand playlistinfo took 2 milliseconds May 29 08:19:30 volumio volumio[1236]: info: sendMpdCommand playlistinfo took 2 milliseconds May 29 08:19:30 volumio volumio[1236]: verbose: ControllerMpd::parseTrackInfo May 29 08:19:30 volumio volumio[1236]: verbose: ControllerMpd::parseTrackInfo May 29 08:19:30 volumio volumio[1236]: verbose: ControllerMpd::parseTrackInfo May 29 08:19:30 volumio volumio[1236]: verbose: ControllerMpd::parseTrackInfo May 29 08:19:30 volumio volumio[1236]: info: ControllerMpd::pushState May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::servicePushState May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::pushState May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::volumioPushState May 29 08:19:30 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:19:30 volumio volumio[1236]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Де ти є","artist":"Epolets","album":"Dogma","uri":"https://rr2---sn-a5oxu-uoae.googlevideo.com/videoplayback?expire=1748517395&ei=s-03aKrWCLmF6dsP-4KF2Qs&ip=5.58.123.88&id=o-AABDwmWGH-AHhjUkSbp7b0CGwgq_LfMF6f3Iq4YXvb-K&itag=774&source=youtube&requiressl=yes&xpc=EgVo2aDSNQ%3D%3D&met=1748495795%2C&mh=Xk&mm=31%2C29&mn=sn-a5oxu-uoae%2Csn-3c27snel&ms=au%2Crdu&mv=m&mvi=2&pl=20&rms=au%2Cau&ctier=A&pfa=5&gcr=ua&initcwndbps=2272500&hightc=yes&siu=1&bui=AY1jyLNVyzINVaaHZYlF-4YYtwM0t7Ovd_z_436BfY2IzpYMln34QP6saggy6rf5RRdeWQCu5A&spc=l3OVKefBXHFsZWYit5XLa7ulkfNj2KOYeQpNb-W1y-Pn_XnGbqXtLSiANwr5xW0&vprv=1&svpuc=1&mime=audio%2Fwebm&ns=RjxvDFkbZmKxrfGwOJLVm08Q&rqh=1&gir=yes&clen=9270340&dur=278.081&lmt=1714746418832926&mt=1748495337&fvip=9&keepalive=yes&c=WEB_REMIX&sefc=1&txp=1318224&n=tiRlIsCTjkrmjA&sparams=expire%2Cei%2Cip%2Cid%2Citag%2Csource%2Crequiressl%2Cxpc%2Cctier%2Cpfa%2Cgcr%2Chightc%2Csiu%2Cbui%2Cspc%2Cvprv%2Csvpuc%2Cmime%2Cns%2Crqh%2Cgir%2Cclen%2Cdur%2Clmt&lsparams=met%2Cmh%2Cmm%2Cmn%2Cms%2Cmv%2Cmvi%2Cpl%2Crms%2Cinitcwndbps&lsig=APaTxxMwRAIgc3SLD6-ynVYDaQBceoKwWtrjvzXvb1ui7Pu6EpsN-9QCIBrQAbITkgyewmgA_CLo6fru8_P2e8KbsthvSUzsIYYZ&sig=AJfQdSswRQIgFdGWCJRcU4DQJqfKNikRcVnWRMLo11T58TRsBi2owHYCIQCVoBdwLHrGoQVNKd0Vni5spuQyAHXVSlHnBxgscCbqlA%3D%3D&pot=Ml8b4MHfbvlenxvctbWyX0c-A4bDm7u3tVkwb0aAzpBIdbhX7Mejz5lQDVhuWWG67fZNd8S05JjqaNLsk6mobQhauqwlZuE6K-2QXwmHaf8V7lLsdTWi3iubhC80gMdaHw%3D%3D&cver=1.20250219.01.00&t.YouTube","trackType":"YouTube"} May 29 08:19:30 volumio volumio[1236]: verbose: CURRENT POSITION 4 May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::syncState stateService stop May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::syncState currentStatus stop May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::pushState May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::volumioPushState May 29 08:19:30 volumio volumio[1236]: info: No code May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::pushState May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::volumioPushState May 29 08:19:30 volumio volumio[1236]: info: ControllerMpd::pushState May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::servicePushState May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::pushState May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::volumioPushState May 29 08:19:30 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:19:30 volumio volumio[1236]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Де ти є","artist":"Epolets","album":"Dogma","uri":"https://rr2---sn-a5oxu-uoae.googlevideo.com/videoplayback?expire=1748517395&ei=s-03aKrWCLmF6dsP-4KF2Qs&ip=5.58.123.88&id=o-AABDwmWGH-AHhjUkSbp7b0CGwgq_LfMF6f3Iq4YXvb-K&itag=774&source=youtube&requiressl=yes&xpc=EgVo2aDSNQ%3D%3D&met=1748495795%2C&mh=Xk&mm=31%2C29&mn=sn-a5oxu-uoae%2Csn-3c27snel&ms=au%2Crdu&mv=m&mvi=2&pl=20&rms=au%2Cau&ctier=A&pfa=5&gcr=ua&initcwndbps=2272500&hightc=yes&siu=1&bui=AY1jyLNVyzINVaaHZYlF-4YYtwM0t7Ovd_z_436BfY2IzpYMln34QP6saggy6rf5RRdeWQCu5A&spc=l3OVKefBXHFsZWYit5XLa7ulkfNj2KOYeQpNb-W1y-Pn_XnGbqXtLSiANwr5xW0&vprv=1&svpuc=1&mime=audio%2Fwebm&ns=RjxvDFkbZmKxrfGwOJLVm08Q&rqh=1&gir=yes&clen=9270340&dur=278.081&lmt=1714746418832926&mt=1748495337&fvip=9&keepalive=yes&c=WEB_REMIX&sefc=1&txp=1318224&n=tiRlIsCTjkrmjA&sparams=expire%2Cei%2Cip%2Cid%2Citag%2Csource%2Crequiressl%2Cxpc%2Cctier%2Cpfa%2Cgcr%2Chightc%2Csiu%2Cbui%2Cspc%2Cvprv%2Csvpuc%2Cmime%2Cns%2Crqh%2Cgir%2Cclen%2Cdur%2Clmt&lsparams=met%2Cmh%2Cmm%2Cmn%2Cms%2Cmv%2Cmvi%2Cpl%2Crms%2Cinitcwndbps&lsig=APaTxxMwRAIgc3SLD6-ynVYDaQBceoKwWtrjvzXvb1ui7Pu6EpsN-9QCIBrQAbITkgyewmgA_CLo6fru8_P2e8KbsthvSUzsIYYZ&sig=AJfQdSswRQIgFdGWCJRcU4DQJqfKNikRcVnWRMLo11T58TRsBi2owHYCIQCVoBdwLHrGoQVNKd0Vni5spuQyAHXVSlHnBxgscCbqlA%3D%3D&pot=Ml8b4MHfbvlenxvctbWyX0c-A4bDm7u3tVkwb0aAzpBIdbhX7Mejz5lQDVhuWWG67fZNd8S05JjqaNLsk6mobQhauqwlZuE6K-2QXwmHaf8V7lLsdTWi3iubhC80gMdaHw%3D%3D&cver=1.20250219.01.00&t.YouTube","trackType":"YouTube"} May 29 08:19:30 volumio volumio[1236]: verbose: CURRENT POSITION 4 May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::syncState stateService stop May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::syncState currentStatus stop May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::pushState May 29 08:19:30 volumio systemd[1]: Stopping peppymeterbasic.service - peppymeterbasic Daemon... May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::volumioPushState May 29 08:19:30 volumio volumio[1236]: info: No code May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::pushState May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::volumioPushState May 29 08:19:30 volumio volumio[1236]: info: ControllerMpd::pushState May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::servicePushState May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::pushState May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::volumioPushState May 29 08:19:30 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:19:30 volumio volumio[1236]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Де ти є","artist":"Epolets","album":"Dogma","uri":"https://rr2---sn-a5oxu-uoae.googlevideo.com/videoplayback?expire=1748517395&ei=s-03aKrWCLmF6dsP-4KF2Qs&ip=5.58.123.88&id=o-AABDwmWGH-AHhjUkSbp7b0CGwgq_LfMF6f3Iq4YXvb-K&itag=774&source=youtube&requiressl=yes&xpc=EgVo2aDSNQ%3D%3D&met=1748495795%2C&mh=Xk&mm=31%2C29&mn=sn-a5oxu-uoae%2Csn-3c27snel&ms=au%2Crdu&mv=m&mvi=2&pl=20&rms=au%2Cau&ctier=A&pfa=5&gcr=ua&initcwndbps=2272500&hightc=yes&siu=1&bui=AY1jyLNVyzINVaaHZYlF-4YYtwM0t7Ovd_z_436BfY2IzpYMln34QP6saggy6rf5RRdeWQCu5A&spc=l3OVKefBXHFsZWYit5XLa7ulkfNj2KOYeQpNb-W1y-Pn_XnGbqXtLSiANwr5xW0&vprv=1&svpuc=1&mime=audio%2Fwebm&ns=RjxvDFkbZmKxrfGwOJLVm08Q&rqh=1&gir=yes&clen=9270340&dur=278.081&lmt=1714746418832926&mt=1748495337&fvip=9&keepalive=yes&c=WEB_REMIX&sefc=1&txp=1318224&n=tiRlIsCTjkrmjA&sparams=expire%2Cei%2Cip%2Cid%2Citag%2Csource%2Crequiressl%2Cxpc%2Cctier%2Cpfa%2Cgcr%2Chightc%2Csiu%2Cbui%2Cspc%2Cvprv%2Csvpuc%2Cmime%2Cns%2Crqh%2Cgir%2Cclen%2Cdur%2Clmt&lsparams=met%2Cmh%2Cmm%2Cmn%2Cms%2Cmv%2Cmvi%2Cpl%2Crms%2Cinitcwndbps&lsig=APaTxxMwRAIgc3SLD6-ynVYDaQBceoKwWtrjvzXvb1ui7Pu6EpsN-9QCIBrQAbITkgyewmgA_CLo6fru8_P2e8KbsthvSUzsIYYZ&sig=AJfQdSswRQIgFdGWCJRcU4DQJqfKNikRcVnWRMLo11T58TRsBi2owHYCIQCVoBdwLHrGoQVNKd0Vni5spuQyAHXVSlHnBxgscCbqlA%3D%3D&pot=Ml8b4MHfbvlenxvctbWyX0c-A4bDm7u3tVkwb0aAzpBIdbhX7Mejz5lQDVhuWWG67fZNd8S05JjqaNLsk6mobQhauqwlZuE6K-2QXwmHaf8V7lLsdTWi3iubhC80gMdaHw%3D%3D&cver=1.20250219.01.00&t.YouTube","trackType":"YouTube"} May 29 08:19:30 volumio volumio[1236]: verbose: CURRENT POSITION 4 May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::syncState stateService stop May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::syncState currentStatus stop May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::pushState May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::volumioPushState May 29 08:19:30 volumio volumio[1236]: info: No code May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::pushState May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::volumioPushState May 29 08:19:30 volumio volumio[1236]: info: ControllerMpd::pushState May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::servicePushState May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::pushState May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::volumioPushState May 29 08:19:30 volumio volumio[1236]: info: CorePlayQueue::getTrack 4 May 29 08:19:30 volumio volumio[1236]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Де ти є","artist":"Epolets","album":"Dogma","uri":"https://rr2---sn-a5oxu-uoae.googlevideo.com/videoplayback?expire=1748517395&ei=s-03aKrWCLmF6dsP-4KF2Qs&ip=5.58.123.88&id=o-AABDwmWGH-AHhjUkSbp7b0CGwgq_LfMF6f3Iq4YXvb-K&itag=774&source=youtube&requiressl=yes&xpc=EgVo2aDSNQ%3D%3D&met=1748495795%2C&mh=Xk&mm=31%2C29&mn=sn-a5oxu-uoae%2Csn-3c27snel&ms=au%2Crdu&mv=m&mvi=2&pl=20&rms=au%2Cau&ctier=A&pfa=5&gcr=ua&initcwndbps=2272500&hightc=yes&siu=1&bui=AY1jyLNVyzINVaaHZYlF-4YYtwM0t7Ovd_z_436BfY2IzpYMln34QP6saggy6rf5RRdeWQCu5A&spc=l3OVKefBXHFsZWYit5XLa7ulkfNj2KOYeQpNb-W1y-Pn_XnGbqXtLSiANwr5xW0&vprv=1&svpuc=1&mime=audio%2Fwebm&ns=RjxvDFkbZmKxrfGwOJLVm08Q&rqh=1&gir=yes&clen=9270340&dur=278.081&lmt=1714746418832926&mt=1748495337&fvip=9&keepalive=yes&c=WEB_REMIX&sefc=1&txp=1318224&n=tiRlIsCTjkrmjA&sparams=expire%2Cei%2Cip%2Cid%2Citag%2Csource%2Crequiressl%2Cxpc%2Cctier%2Cpfa%2Cgcr%2Chightc%2Csiu%2Cbui%2Cspc%2Cvprv%2Csvpuc%2Cmime%2Cns%2Crqh%2Cgir%2Cclen%2Cdur%2Clmt&lsparams=met%2Cmh%2Cmm%2Cmn%2Cms%2Cmv%2Cmvi%2Cpl%2Crms%2Cinitcwndbps&lsig=APaTxxMwRAIgc3SLD6-ynVYDaQBceoKwWtrjvzXvb1ui7Pu6EpsN-9QCIBrQAbITkgyewmgA_CLo6fru8_P2e8KbsthvSUzsIYYZ&sig=AJfQdSswRQIgFdGWCJRcU4DQJqfKNikRcVnWRMLo11T58TRsBi2owHYCIQCVoBdwLHrGoQVNKd0Vni5spuQyAHXVSlHnBxgscCbqlA%3D%3D&pot=Ml8b4MHfbvlenxvctbWyX0c-A4bDm7u3tVkwb0aAzpBIdbhX7Mejz5lQDVhuWWG67fZNd8S05JjqaNLsk6mobQhauqwlZuE6K-2QXwmHaf8V7lLsdTWi3iubhC80gMdaHw%3D%3D&cver=1.20250219.01.00&t.YouTube","trackType":"YouTube"} May 29 08:19:30 volumio volumio[1236]: verbose: CURRENT POSITION 4 May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::syncState stateService stop May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::syncState currentStatus stop May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::pushState May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::volumioPushState May 29 08:19:30 volumio volumio[1236]: info: No code May 29 08:19:30 volumio volumio[1236]: info: CoreStateMachine::pushState May 29 08:19:30 volumio volumio[1236]: info: CoreCommandRouter::volumioPushState May 29 08:19:30 volumio volumio[1236]: info: ------------------------------ 53ms May 29 08:19:30 volumio volumio[1236]: info: ------------------------------ 52ms May 29 08:19:30 volumio volumio[1236]: info: ------------------------------ 53ms May 29 08:19:30 volumio volumio[1236]: info: ------------------------------ 52ms May 29 08:19:30 volumio volumio[1236]: info: PeppyMeterBasic ---peppymeterbasic status play May 29 08:19:30 volumio volumio[1236]: info: PeppyMeterBasic ---peppymeterbasic status play May 29 08:19:30 volumio sudo[6153]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service May 29 08:19:30 volumio volumio[1236]: info: PeppyMeterBasic ---peppymeterbasic status play May 29 08:19:30 volumio sudo[6153]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:19:30 volumio volumio[1236]: info: PeppyMeterBasic ---peppymeterbasic status play May 29 08:19:30 volumio sudo[6155]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service May 29 08:19:30 volumio sudo[6155]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:19:30 volumio sudo[6148]: pam_unix(sudo:session): session closed for user root May 29 08:19:30 volumio volumio[1236]: info: PeppyMeterBasic ---peppymeterbasic status play May 29 08:19:30 volumio volumio[1236]: info: PeppyMeterBasic ---peppymeterbasic status play May 29 08:19:30 volumio sudo[6160]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service May 29 08:19:30 volumio sudo[6160]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:19:30 volumio sudo[6161]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service May 29 08:19:30 volumio sudo[6163]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service May 29 08:19:30 volumio systemd[1]: peppymeterbasic.service: Deactivated successfully. May 29 08:19:30 volumio sudo[6163]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:19:30 volumio systemd[1]: peppymeterbasic.service: Consumed 18.882s CPU time. May 29 08:19:30 volumio sudo[6161]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:19:30 volumio volumio[1236]: info: PeppyMeterBasic ---peppymeterbasic status play May 29 08:19:30 volumio volumio[1236]: info: PeppyMeterBasic ---peppymeterbasic status play May 29 08:19:30 volumio sudo[6168]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service May 29 08:19:30 volumio sudo[6168]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:19:30 volumio volumio[1236]: info: PeppyMeterBasic ---peppymeterbasic status play May 29 08:19:30 volumio sudo[6171]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service May 29 08:19:30 volumio sudo[6171]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:19:30 volumio systemd[1]: Started peppymeterbasic.service - peppymeterbasic Daemon. May 29 08:19:30 volumio sudo[6174]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service May 29 08:19:30 volumio sudo[6174]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:19:30 volumio sudo[6155]: pam_unix(sudo:session): session closed for user root May 29 08:19:30 volumio volumio[1236]: info: PeppyMeterBasic ---peppymeterbasic status play May 29 08:19:30 volumio volumio[1236]: info: PeppyMeterBasic ---peppymeterbasic status play May 29 08:19:30 volumio sudo[6153]: pam_unix(sudo:session): session closed for user root May 29 08:19:30 volumio sudo[6179]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service May 29 08:19:30 volumio sudo[6179]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:19:30 volumio volumio[1236]: info: PeppyMeterBasic ---peppymeterbasic status play May 29 08:19:30 volumio sudo[6160]: pam_unix(sudo:session): session closed for user root May 29 08:19:30 volumio sudo[6163]: pam_unix(sudo:session): session closed for user root May 29 08:19:30 volumio sudo[6161]: pam_unix(sudo:session): session closed for user root May 29 08:19:30 volumio sudo[6171]: pam_unix(sudo:session): session closed for user root May 29 08:19:30 volumio sudo[6168]: pam_unix(sudo:session): session closed for user root May 29 08:19:30 volumio sudo[6174]: pam_unix(sudo:session): session closed for user root May 29 08:19:30 volumio sudo[6181]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service May 29 08:19:30 volumio sudo[6181]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:19:30 volumio sudo[6179]: pam_unix(sudo:session): session closed for user root May 29 08:19:30 volumio sudo[6187]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service May 29 08:19:30 volumio sudo[6187]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:19:30 volumio sudo[6186]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service May 29 08:19:30 volumio sudo[6181]: pam_unix(sudo:session): session closed for user root May 29 08:19:30 volumio sudo[6186]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio sudo[6187]: pam_unix(sudo:session): session closed for user root May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio sudo[6186]: pam_unix(sudo:session): session closed for user root May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:19:30 volumio volumio[1236]: info: peppymeterbasic Daemon Started May 29 08:19:30 volumio volumio[1236]: info: peppymeterbasic Daemon Started May 29 08:19:30 volumio volumio[1236]: info: peppymeterbasic Daemon Started May 29 08:19:30 volumio volumio[1236]: info: peppymeterbasic Daemon Started May 29 08:19:30 volumio volumio[1236]: info: peppymeterbasic Daemon Started May 29 08:19:30 volumio volumio[1236]: info: peppymeterbasic Daemon Started May 29 08:19:30 volumio volumio[1236]: info: peppymeterbasic Daemon Started May 29 08:19:30 volumio volumio[1236]: info: peppymeterbasic Daemon Started May 29 08:19:30 volumio volumio[1236]: info: peppymeterbasic Daemon Started May 29 08:19:30 volumio volumio[1236]: info: peppymeterbasic Daemon Started May 29 08:19:30 volumio volumio[1236]: info: peppymeterbasic Daemon Started May 29 08:19:30 volumio volumio[1236]: info: peppymeterbasic Daemon Started May 29 08:19:30 volumio volumio[1236]: info: PeppyMeterBasic ---peppymeterbasic failed to stop!! Error: Command failed: /usr/bin/sudo /bin/systemctl stop peppymeterbasic.service May 29 08:19:30 volumio volumio[1236]: Job for peppymeterbasic.service canceled. May 29 08:19:31 volumio volumio[1236]: info: CoreCommandRouter::volumioPushQueue May 29 08:19:31 volumio volumio[1236]: info: CorePlayQueue::saveQueue May 29 08:19:31 volumio volumio[1236]: info: CoreStateMachine::updateTrackBlock May 29 08:19:31 volumio volumio[1236]: info: CorePlayQueue::getTrackBlock May 29 08:19:31 volumio volumio[1236]: info: CoreCommandRouter::volumioPlay May 29 08:19:31 volumio volumio[1236]: info: CoreStateMachine::play index 0 May 29 08:19:31 volumio volumio[1236]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:19:31 volumio volumio[1236]: info: CoreStateMachine::stop May 29 08:19:31 volumio volumio[1236]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:19:31 volumio volumio[1236]: info: CoreStateMachine::play index undefined May 29 08:19:31 volumio volumio[1236]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:19:31 volumio volumio[1236]: info: CorePlayQueue::getTrack 0 May 29 08:19:31 volumio volumio[1236]: info: CoreStateMachine::startPlaybackTimer May 29 08:19:31 volumio volumio[1236]: info: CorePlayQueue::getTrack 0 May 29 08:19:31 volumio volumio[1236]: info: [1748495971584] ControllerSpotify::clearAddPlayTrack May 29 08:19:31 volumio volumio[1236]: info: Sending Spotify command with payload to local API: /player/play May 29 08:19:31 volumio go-librespot[6062]: time="2025-05-29T08:19:31+03:00" level=debug msg="resolved context of track" uri="spotify:track:5jedbiUszLM2dVnlM2t1Cl" May 29 08:19:31 volumio go-librespot[6062]: time="2025-05-29T08:19:31+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:5jedbiUszLM2dVnlM2t1Cl" May 29 08:19:31 volumio go-librespot[6062]: time="2025-05-29T08:19:31+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5jedbiUszLM2dVnlM2t1Cl" May 29 08:19:31 volumio go-librespot[6062]: time="2025-05-29T08:19:31+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 29 08:19:31 volumio go-librespot[6062]: time="2025-05-29T08:19:31+03:00" level=trace msg="emitting websocket event: will_play" May 29 08:19:31 volumio volumio[1236]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5jedbiUszLM2dVnlM2t1Cl","play_origin":"go-librespot"}} May 29 08:19:31 volumio volumio[1236]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5jedbiUszLM2dVnlM2t1Cl","play_origin":"go-librespot"}} May 29 08:19:31 volumio volumio[1236]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5jedbiUszLM2dVnlM2t1Cl","play_origin":"go-librespot"}} May 29 08:19:31 volumio volumio[1236]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5jedbiUszLM2dVnlM2t1Cl","play_origin":"go-librespot"}} May 29 08:19:31 volumio go-librespot[6062]: time="2025-05-29T08:19:31+03:00" level=debug msg="selected format OGG_VORBIS_320 (9855401ef9afe1cc041daca3614885dafae26c52)" uri="spotify:track:5jedbiUszLM2dVnlM2t1Cl" May 29 08:19:31 volumio go-librespot[6062]: time="2025-05-29T08:19:31+03:00" level=debug msg="requested aes key for file 9855401ef9afe1cc041daca3614885dafae26c52, gid: 5jedbiUszLM2dVnlM2t1Cl" May 29 08:19:31 volumio go-librespot[6062]: time="2025-05-29T08:19:31+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 29 08:19:31 volumio go-librespot[6062]: time="2025-05-29T08:19:31+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 29 08:19:31 volumio go-librespot[6062]: time="2025-05-29T08:19:31+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 29 08:19:31 volumio go-librespot[6062]: time="2025-05-29T08:19:31+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1358" May 29 08:19:32 volumio go-librespot[6062]: time="2025-05-29T08:19:32+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 29 08:19:32 volumio go-librespot[6062]: time="2025-05-29T08:19:32+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1123" May 29 08:19:33 volumio go-librespot[6062]: time="2025-05-29T08:19:33+03:00" level=debug msg="fetched first chunk of 11, total size is 5748354 bytes" uri="spotify:track:5jedbiUszLM2dVnlM2t1Cl" May 29 08:19:33 volumio go-librespot[6062]: time="2025-05-29T08:19:33+03:00" level=debug msg="created new output device" May 29 08:19:33 volumio go-librespot[6062]: time="2025-05-29T08:19:33+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" May 29 08:19:33 volumio go-librespot[6062]: time="2025-05-29T08:19:33+03:00" level=info msg="loaded track \"На долині туман\" (paused: false, position: 0ms, duration: 140160ms, prefetched: false)" uri="spotify:track:5jedbiUszLM2dVnlM2t1Cl" May 29 08:19:33 volumio go-librespot[6062]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. May 29 08:19:33 volumio go-librespot[6061]: Aborted May 29 08:19:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a May 29 08:19:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 29 08:19:33 volumio volumio[1236]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:19:33 volumio volumio[1236]: info: Connection to go-librespot Websocket closed May 29 08:19:33 volumio volumio[1236]: info: Connection to go-librespot Websocket closed May 29 08:19:33 volumio volumio[1236]: info: Connection to go-librespot Websocket closed May 29 08:19:33 volumio volumio[1236]: info: Connection to go-librespot Websocket closed May 29 08:19:36 volumio volumio[1236]: info: Initializing connection to go-librespot Websocket May 29 08:19:36 volumio volumio[1236]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 29 08:19:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. May 29 08:19:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 29 08:19:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 29 08:19:36 volumio go-librespot[6203]: go-librespot daemon starting... May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=info msg="running go-librespot 0.2.0" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=debug msg="app state loaded" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=info msg="api server listening on 127.0.0.1:9879" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=info msg="zeroconf server listening on port 41995" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=debug msg="obtained new client token: AACxrvwpMq4J8kThODWLQ87v4GXS9bydOHAp9Y46uHyV5pJchxjmVAHEzhE7fLypalrwJ25IFGjyfjRA6RAs6HHzayQreN5TK59WR2J86mFJAwYg+n0IfjmJgtnmhvfBPYZ7GGT9dO9ynKeMKxCjABJ9Ut+gEl0ffr8IDcOfYL92kydBxdZ87v4KM/xanOwix6kCZVqM0gYl4U8K+jFarlFcWiK+Dv1pc2YKw8bO2fCfxuSwQAH6" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=debug msg="completed keyexchange" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=debug msg="completed challenge" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=info msg="authenticated AP as pb5pp9zr5gss9vfrrdysusbut" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=info msg="authenticated Login5 as pb5pp9zr5gss9vfrrdysusbut" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=debug msg="initializing zeroconf session, username: pb5pp9zr5gss9vfrrdysusbut" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=debug msg="dealer connection opened" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=trace msg="starting accesspoint recv loop" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=trace msg="starting dealer recv loop" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=trace msg="received accesspoint ping" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=debug msg="received connection id: OWU2MjBkODYtNWRjOC00ZGI4LWFjMzQtM2Y0M2FkYzFhYjc5K2RlYWxlcit0Y3A6Ly8wYWNhNDI1Ni5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMENEQTM5ODVDNUMxRUI3ODI0M0I1QTI1QUMwMkNBM0QzODlBMzNEMTkxOUUyMDc0ODUxNUZCNDk1QzIwMDVFQQ==" May 29 08:19:36 volumio go-librespot[6204]: time="2025-05-29T08:19:36+03:00" level=trace msg="received accesspoint pong ack" May 29 08:19:37 volumio go-librespot[6204]: time="2025-05-29T08:19:37+03:00" level=debug msg="put connect state because NEW_DEVICE" May 29 08:19:39 volumio volumio[1236]: info: Initializing connection to go-librespot Websocket May 29 08:19:39 volumio go-librespot[6204]: time="2025-05-29T08:19:39+03:00" level=debug msg="new websocket client" May 29 08:19:39 volumio volumio[1236]: info: Connection to go-librespot Websocket established May 29 08:19:40 volumio volumio[1236]: info: Preload queue cleared May 29 08:19:40 volumio volumio[1236]: info: CoreCommandRouter::volumioReplaceandPlayItems May 29 08:19:40 volumio volumio[1236]: info: CoreStateMachine::ClearQueue May 29 08:19:40 volumio volumio[1236]: info: CoreStateMachine::stop May 29 08:19:40 volumio volumio[1236]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:19:40 volumio volumio[1236]: info: CorePlayQueue::clearPlayQueue May 29 08:19:40 volumio volumio[1236]: info: CorePlayQueue::saveQueue May 29 08:19:40 volumio volumio[1236]: info: CoreCommandRouter::volumioPushQueue May 29 08:19:40 volumio volumio[1236]: info: CoreStateMachine::addQueueItems May 29 08:19:40 volumio volumio[1236]: info: CorePlayQueue::addQueueItems May 29 08:19:40 volumio volumio[1236]: info: Preload queue cleared May 29 08:19:40 volumio volumio[1236]: info: Adding Item to queue: spotify:playlist:37i9dQZF1DX2X2YHi92QqA May 29 08:19:40 volumio volumio[1236]: info: Using cached record of: spotify:playlist:37i9dQZF1DX2X2YHi92QqA May 29 08:19:40 volumio volumio[1236]: info: CoreCommandRouter::volumioPushQueue May 29 08:19:40 volumio volumio[1236]: info: CorePlayQueue::saveQueue May 29 08:19:40 volumio volumio[1236]: info: CoreStateMachine::updateTrackBlock May 29 08:19:40 volumio volumio[1236]: info: CorePlayQueue::getTrackBlock May 29 08:19:40 volumio volumio[1236]: info: CoreCommandRouter::volumioPlay May 29 08:19:40 volumio volumio[1236]: info: CoreStateMachine::play index 0 May 29 08:19:40 volumio volumio[1236]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:19:40 volumio volumio[1236]: info: CoreStateMachine::stop May 29 08:19:40 volumio volumio[1236]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:19:40 volumio volumio[1236]: info: CoreStateMachine::play index undefined May 29 08:19:40 volumio volumio[1236]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:19:40 volumio volumio[1236]: info: CorePlayQueue::getTrack 0 May 29 08:19:40 volumio volumio[1236]: info: CoreStateMachine::startPlaybackTimer May 29 08:19:40 volumio volumio[1236]: info: CorePlayQueue::getTrack 0 May 29 08:19:40 volumio volumio[1236]: info: [1748495980103] ControllerSpotify::clearAddPlayTrack May 29 08:19:40 volumio volumio[1236]: info: Sending Spotify command with payload to local API: /player/play May 29 08:19:40 volumio go-librespot[6204]: time="2025-05-29T08:19:40+03:00" level=debug msg="resolved context of track" uri="spotify:track:5jedbiUszLM2dVnlM2t1Cl" May 29 08:19:40 volumio go-librespot[6204]: time="2025-05-29T08:19:40+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:5jedbiUszLM2dVnlM2t1Cl" May 29 08:19:40 volumio go-librespot[6204]: time="2025-05-29T08:19:40+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5jedbiUszLM2dVnlM2t1Cl" May 29 08:19:40 volumio go-librespot[6204]: time="2025-05-29T08:19:40+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 29 08:19:40 volumio go-librespot[6204]: time="2025-05-29T08:19:40+03:00" level=trace msg="emitting websocket event: will_play" May 29 08:19:40 volumio volumio[1236]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5jedbiUszLM2dVnlM2t1Cl","play_origin":"go-librespot"}} May 29 08:19:40 volumio go-librespot[6204]: time="2025-05-29T08:19:40+03:00" level=debug msg="selected format OGG_VORBIS_320 (9855401ef9afe1cc041daca3614885dafae26c52)" uri="spotify:track:5jedbiUszLM2dVnlM2t1Cl" May 29 08:19:40 volumio go-librespot[6204]: time="2025-05-29T08:19:40+03:00" level=debug msg="requested aes key for file 9855401ef9afe1cc041daca3614885dafae26c52, gid: 5jedbiUszLM2dVnlM2t1Cl" May 29 08:19:40 volumio go-librespot[6204]: time="2025-05-29T08:19:40+03:00" level=debug msg="fetched first chunk of 11, total size is 5748354 bytes" uri="spotify:track:5jedbiUszLM2dVnlM2t1Cl" May 29 08:19:40 volumio go-librespot[6204]: time="2025-05-29T08:19:40+03:00" level=debug msg="created new output device" May 29 08:19:40 volumio go-librespot[6204]: time="2025-05-29T08:19:40+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" May 29 08:19:40 volumio go-librespot[6204]: time="2025-05-29T08:19:40+03:00" level=info msg="loaded track \"На долині туман\" (paused: false, position: 0ms, duration: 140160ms, prefetched: false)" uri="spotify:track:5jedbiUszLM2dVnlM2t1Cl" May 29 08:19:40 volumio go-librespot[6204]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. May 29 08:19:40 volumio go-librespot[6203]: Aborted May 29 08:19:40 volumio volumio[1236]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:19:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a May 29 08:19:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 29 08:19:40 volumio volumio[1236]: info: Connection to go-librespot Websocket closed May 29 08:19:40 volumio volumio[1236]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 29 08:19:40 volumio volumio[1236]: info: In handleBrowseUri, curUri=spotify:playlist:37i9dQZF1DX2X2YHi92QqA May 29 08:19:41 volumio volumio[1236]: info: Preload queue cleared May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:5jedbiUszLM2dVnlM2t1Cl May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:4cET4ZW2fL3Xb4bMaAOS1R May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:4EYKW0U2jc3pJuynL0EWtj May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:3qSb7rjUgUwjpd2EPENnJ9 May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:1VkvQ1JiaMWO3n62QHyclg May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:5q3jGywKjTjrn9nDrbWWdQ May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:0MuhghJcwjnYKjA85A1LI9 May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:61VvYCdAyDoVSxggJXfyS2 May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:3ok1m9sRQbIFzNRmjsTSmj May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:24zC0PezJHu28IGWGKuBqi May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:0MLGNvz1nG6HHjl18ipisV May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:0HVnaML1M41ACk570JuGK8 May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:6aTEg2WEAc6tNWGbQtVgbi May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:1D9nzDnqnSVLoSpKDYAG79 May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:1OJ7eFvEXgLhrH6ggW1Ot3 May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:4ULR3qEOQbMAb5YqE9pCIk May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:2EpaopmDJIeXKcnRCmIeD1 May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:3i3mIwgx2y6KCb1Zg1B09u May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:3D0yIqLOW0MRQdlgZkSCqp May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:0NYvacFqoJdJggiOynzbur May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:3ODfNdDz9b9VmABFncYmPG May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:1gEOO9uivwxwAKIF5Z0ezH May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:5r2e2ZLwP33ASZroY74xWs May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:1K5SDiluaKbKgT4a3hNjXW May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:24dWmtD9a5XoCWBrjVhi7H May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:3GOrxgUNyAcp2i3cdtE31H May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:7DpRyhc5dbAYAiWalOu237 May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:3zglADNq7MNEUAlJfUr710 May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:4AS9O91OqMi1gZ4zq2UiA0 May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:3XnlFqg6yK1kjeIXJqCGbX May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:2YSQRS9wSSIO7z5YOPdytQ May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:1I38Y9qVi1xENY953nqyce May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:5io7Rv6WxpvkqCRreCvXGc May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:5fcel9gZJlpw4KlNS4JksT May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:5sDurqXbFYuIW4rKwkPI07 May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:5rzAUaBEjSgtFVCBXNS9z8 May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:1ldDMlNDXAvW2Bd2O7sOAm May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:4nItE7XjbT1qn2PY4cm4iU May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:3YdeXVe2cwGjHOCsgDPXsb May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:2QCiHiZdEJLywIL28vbrcd May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:33ve7gKEeUALVEIJPCV0zL May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:1hiu3tSlzuEq4QevzENFLA May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:4HgC35ZxqeGWzOtSayjA7X May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:566YyTtP77DESGJKRELSn0 May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:7jo2Jo9WX20nkMmtMoMWCP May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:1o1oxk5yaJ8zwCTWtFriYI May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:0LrxqTCzZ5O67u3rK52wg8 May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:1DgLyjvwcodlM0KbaffvHc May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:3lWeGHj6OYhnYSMVNUi8G4 May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:77otQjwN6OdB4tn6sOCeip May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:4eXCbY7aEJ7KVLmoI0hXaW May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:2PqtiIAHQhZfOH5GTAonYt May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:65zc8JAIiF5vfdccKfE5Y1 May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:0wyOffrr3CrsYYaQkocRgP May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:36E4Bx4P0RvsYnwSu7SbM2 May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:43SR6SwcVhw6ArmGgcy9kD May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:5SVUKYj1FEycD7nir3l53g May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:6xfXvPKTvGEo5xAXcuiIr5 May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:00h9eif2nfiEA1ykBFLvBZ May 29 08:19:41 volumio volumio[1236]: info: Preloading song: spotify:track:13MWdZooAx11yfX2DR5zXt May 29 08:19:41 volumio volumio[1236]: info: Exploding uri spotify:track:5jedbiUszLM2dVnlM2t1Cl in service spop May 29 08:19:41 volumio volumio[1236]: SPOTIFY: EXPLODING URI:spotify:track:5jedbiUszLM2dVnlM2t1Cl May 29 08:19:42 volumio volumio[1236]: info: Exploding uri spotify:track:4cET4ZW2fL3Xb4bMaAOS1R in service spop May 29 08:19:42 volumio volumio[1236]: SPOTIFY: EXPLODING URI:spotify:track:4cET4ZW2fL3Xb4bMaAOS1R May 29 08:19:42 volumio volumio[1236]: info: Exploding uri spotify:track:4EYKW0U2jc3pJuynL0EWtj in service spop May 29 08:19:42 volumio volumio[1236]: SPOTIFY: EXPLODING URI:spotify:track:4EYKW0U2jc3pJuynL0EWtj May 29 08:19:42 volumio volumio[1236]: info: Exploding uri spotify:track:3qSb7rjUgUwjpd2EPENnJ9 in service spop May 29 08:19:42 volumio volumio[1236]: SPOTIFY: EXPLODING URI:spotify:track:3qSb7rjUgUwjpd2EPENnJ9 May 29 08:19:42 volumio volumio[1236]: info: Getting Spotify volume May 29 08:19:42 volumio volumio[1236]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 29 08:19:42 volumio volumio[1236]: Error: connect ECONNREFUSED 127.0.0.1:9879 May 29 08:19:42 volumio volumio[1236]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { May 29 08:19:42 volumio volumio[1236]: errno: -111, May 29 08:19:42 volumio volumio[1236]: code: 'ECONNREFUSED', May 29 08:19:42 volumio volumio[1236]: syscall: 'connect', May 29 08:19:42 volumio volumio[1236]: address: '127.0.0.1', May 29 08:19:42 volumio volumio[1236]: port: 9879, May 29 08:19:42 volumio volumio[1236]: response: undefined May 29 08:19:42 volumio volumio[1236]: } May 29 08:19:42 volumio volumio[1236]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 29 08:19:42 volumio sudo[6242]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-05-29 08:18' May 29 08:19:42 volumio sudo[6242]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="fd567ba9bc0dc34c0403e2d5b72a0f46467d1983" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri May 23 07:33:33 UTC 2025" VOLUMIO_VERSION="0.069" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="d67a2da4ffe3f001e986b1f31eaa3a76"