Dec 29 17:56:20 volumio-lounge volumio[1287]: info: Received OAUTH Data Dec 29 17:56:20 volumio-lounge volumio[1287]: info: Executing Spotify Oauth Login Dec 29 17:56:20 volumio-lounge volumio[1287]: info: Saving Spotify Refresh Token Dec 29 17:56:20 volumio-lounge volumio[1287]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 29 17:56:20 volumio-lounge volumio[1287]: SPOTIFY: BQAswcUY5nZsqnlQD6_Yk1q4lIzDtqxVvqdsJ4-fl-fYIBZWHbu5qZ_sJULz0zAM7rKi0jh-Sl0a0XjAWfYKVmH75nArxZ-qt01u06VQ30oxMxyDtMXzYFLPAnNUWOUrjR1BjxOhUeLWHem54lKS_ExtlGSoGz0ChC922XsiiG_84JPSLJKU2gQNWaJedYW7WMsuvq2tc-w5BVeEMyjaRrEo97UUHvjg-wkavwc3xZbtMgNLVlILM9-_oDkJJZtld12gDN0PaaoLTXFUJI6OZk9nRuQXwKv0-Q Dec 29 17:56:20 volumio-lounge volumio[1287]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 29 17:56:20 volumio-lounge volumio[1287]: info: New Spotify access token = BQAswcUY5nZsqnlQD6_Yk1q4lIzDtqxVvqdsJ4-fl-fYIBZWHbu5qZ_sJULz0zAM7rKi0jh-Sl0a0XjAWfYKVmH75nArxZ-qt01u06VQ30oxMxyDtMXzYFLPAnNUWOUrjR1BjxOhUeLWHem54lKS_ExtlGSoGz0ChC922XsiiG_84JPSLJKU2gQNWaJedYW7WMsuvq2tc-w5BVeEMyjaRrEo97UUHvjg-wkavwc3xZbtMgNLVlILM9-_oDkJJZtld12gDN0PaaoLTXFUJI6OZk9nRuQXwKv0-Q Dec 29 17:56:20 volumio-lounge volumio[1287]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 29 17:56:21 volumio-lounge volumio[1287]: SPOTIFY: User informations: {"country":"GB","display_name":"ldkirton","email":"liam@int3.ws","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/ldkirton"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/ldkirton","id":"ldkirton","images":[],"product":"premium","type":"user","uri":"spotify:user:ldkirton"} Dec 29 17:56:21 volumio-lounge volumio[1287]: info: Creating Spotify config file Dec 29 17:56:21 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 17:56:21 volumio-lounge volumio[1287]: info: Spotify config file written Dec 29 17:56:21 volumio-lounge sudo[3258]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 29 17:56:21 volumio-lounge sudo[3258]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 17:56:21 volumio-lounge sudo[3261]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 29 17:56:21 volumio-lounge sudo[3261]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 17:56:21 volumio-lounge systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 29 17:56:21 volumio-lounge systemd[1]: go-librespot-daemon.service: Killing process 3181 (go-librespot) with signal SIGKILL. Dec 29 17:56:21 volumio-lounge sudo[3261]: pam_unix(sudo:session): session closed for user root Dec 29 17:56:21 volumio-lounge systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 29 17:56:21 volumio-lounge systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 17:56:21 volumio-lounge volumio[1287]: info: Connection to go-librespot Websocket closed Dec 29 17:56:21 volumio-lounge volumio[1287]: info: Connection to go-librespot Websocket closed Dec 29 17:56:21 volumio-lounge sudo[3263]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 29 17:56:21 volumio-lounge sudo[3263]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 17:56:21 volumio-lounge sudo[3263]: pam_unix(sudo:session): session closed for user root Dec 29 17:56:21 volumio-lounge volumio[1287]: verbose: New Socket.io Connection to 10.0.64.131 from 10.0.48.104 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/145.0.0.0 Safari/537.36 Edg/145.0.0.0 Engine version: 3 Transport: polling Total Clients: 7 Dec 29 17:56:21 volumio-lounge systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 17:56:21 volumio-lounge go-librespot[3265]: go-librespot daemon starting... Dec 29 17:56:21 volumio-lounge sudo[3258]: pam_unix(sudo:session): session closed for user root Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=info msg="running go-librespot 0.4.0" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=debug msg="app state loaded" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=debug msg="stored credentials not found" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 17:56:21 volumio-lounge volumio[1287]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 29 17:56:21 volumio-lounge volumio[1287]: SPOTIFY: BQCU9lD5mEBT5a-vpnkG1EvLZvovSg11YpwE9regsdHqJS87luHy9O3v6Y6yU8ZqAx3cybiiIvZSVp6fRpxGfnatNbSP3xScZgL1BFSR-IqvZDAiknX_UEpQHXrg9OCekNcff90P0s0lX-rRcsE5765ylw0OY4gEzwZU_wftOmMDw37fxvbdIoXFhRSoPKCnRSBm5_79eUGtmXEC1KI1Rih8P5-e2np_W3P1I2gmq0vHwXr_a46W4DdEdAG_7PPhYtOCKxJDowNywbhVRIB9fV6C9oTBenqO4w Dec 29 17:56:21 volumio-lounge volumio[1287]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 29 17:56:21 volumio-lounge volumio[1287]: info: New Spotify access token = BQCU9lD5mEBT5a-vpnkG1EvLZvovSg11YpwE9regsdHqJS87luHy9O3v6Y6yU8ZqAx3cybiiIvZSVp6fRpxGfnatNbSP3xScZgL1BFSR-IqvZDAiknX_UEpQHXrg9OCekNcff90P0s0lX-rRcsE5765ylw0OY4gEzwZU_wftOmMDw37fxvbdIoXFhRSoPKCnRSBm5_79eUGtmXEC1KI1Rih8P5-e2np_W3P1I2gmq0vHwXr_a46W4DdEdAG_7PPhYtOCKxJDowNywbhVRIB9fV6C9oTBenqO4w Dec 29 17:56:21 volumio-lounge volumio[1287]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 29 17:56:21 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 29 17:56:21 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetVisibleSources Dec 29 17:56:21 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 17:56:21 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetState Dec 29 17:56:21 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 29 17:56:21 volumio-lounge volumio[1287]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 29 17:56:21 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 29 17:56:21 volumio-lounge volumio[1287]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Dec 29 17:56:21 volumio-lounge volumio[1287]: info: Received Get System Info Dec 29 17:56:21 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 29 17:56:21 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 29 17:56:21 volumio-lounge volumio[1287]: info: Discovery: Getting this device information Dec 29 17:56:21 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetState Dec 29 17:56:21 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 29 17:56:21 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetState Dec 29 17:56:21 volumio-lounge volumio[1287]: info: Listing playlists Dec 29 17:56:21 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 29 17:56:21 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 29 17:56:21 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 29 17:56:21 volumio-lounge volumio[1287]: SPOTIFY: User informations: {"country":"GB","display_name":"ldkirton","email":"liam@int3.ws","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/ldkirton"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/ldkirton","id":"ldkirton","images":[],"product":"premium","type":"user","uri":"spotify:user:ldkirton"} Dec 29 17:56:21 volumio-lounge volumio[1287]: info: Spotify Successfully logged in Dec 29 17:56:21 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 29 17:56:21 volumio-lounge volumio[1287]: info: [1767030981475] CoreMusicLibrary::Adding element Spotify Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" 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-gae2.spotify.com:80]" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 29 17:56:21 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 17:56:21 volumio-lounge volumio[1287]: Cannot find translation for source Spotify Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=info msg="zeroconf server listening on port 34001" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=debug msg="obtained new client token: AACTV1cCtDVI+mq045ksHhvnktOj6fMDZdRvdNIUvcvfRc5jfAi+Bjk3vmagaS19+s1WPxb3s6CuycaLINn9vIVOMSuktkc12JC6OIunvWlMtkBwLMLE3upKGwge/coDb+EQYt4AM1UrrfWB2cclHjOJa3P1rGoJxiR3J/QS9k/BUA9C7o7hSYEfDECktEombMQLihf7Sg4tW6zrEY7fAX7B7Jt1ZN9nUd4toVKnuPCdx4JZbxAriPE=" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=debug msg="completed keyexchange" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=debug msg="completed challenge" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=info msg="authenticated AP" username="ld****on" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=info msg="authenticated Login5" username="ld****on" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=debug msg="stored credentials" username="ld****on" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=debug msg="initializing zeroconf session" username="ld****on" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=debug msg="dealer connection opened" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=trace msg="starting accesspoint recv loop" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=trace msg="starting dealer recv loop" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=trace msg="received accesspoint ping" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=debug msg="received connection id: MjI0YTJjZDktM2Vk...MTRGMjg0Mzc4MA==" Dec 29 17:56:21 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:21Z" level=trace msg="received accesspoint pong ack" Dec 29 17:56:22 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:22Z" level=debug msg="put connect state because NEW_DEVICE" Dec 29 17:56:22 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 29 17:56:23 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 29 17:56:23 volumio-lounge volumio[1287]: info: Received Get System Info Dec 29 17:56:23 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 29 17:56:23 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 29 17:56:23 volumio-lounge volumio[1287]: info: Discovery: Getting this device information Dec 29 17:56:23 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetState Dec 29 17:56:23 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 29 17:56:23 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 29 17:56:23 volumio-lounge volumio[1287]: info: Received Get System Info Dec 29 17:56:23 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 29 17:56:23 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 29 17:56:23 volumio-lounge volumio[1287]: info: Discovery: Getting this device information Dec 29 17:56:23 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetState Dec 29 17:56:23 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 29 17:56:24 volumio-lounge volumio[1287]: info: Initializing connection to go-librespot Websocket Dec 29 17:56:24 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:24Z" level=debug msg="new websocket client" Dec 29 17:56:24 volumio-lounge volumio[1287]: info: Connection to go-librespot Websocket established Dec 29 17:56:24 volumio-lounge volumio[1287]: info: go-librespot daemon successfully initialized Dec 29 17:56:27 volumio-lounge volumio[1287]: info: Getting Spotify volume Dec 29 17:56:27 volumio-lounge volumio[1287]: info: Spotify volume: 100 Dec 29 17:56:27 volumio-lounge volumio[1287]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 29 17:56:27 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetState Dec 29 17:56:27 volumio-lounge volumio[1287]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Dec 29 17:56:27 volumio-lounge volumio[1287]: SPOTIFY: SPOTIFY VOLUME 100 Dec 29 17:56:27 volumio-lounge volumio[1287]: SPOTIFY: VOLUMIO VOLUME 54 Dec 29 17:56:27 volumio-lounge volumio[1287]: SPOTIFY: DELTA VOLUME ENOUGH: true Dec 29 17:56:27 volumio-lounge volumio[1287]: info: Setting Spotify Volume from Volumio: 54 Dec 29 17:56:27 volumio-lounge volumio[1287]: info: Initializing connection to go-librespot Websocket Dec 29 17:56:27 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:27Z" level=debug msg="new websocket client" Dec 29 17:56:27 volumio-lounge volumio[1287]: info: Connection to go-librespot Websocket established Dec 29 17:56:28 volumio-lounge volumio[1287]: SPOTIFY: SETTING SPOTIFY VOLUME 54 Dec 29 17:56:28 volumio-lounge volumio[1287]: info: Sending Spotify command with payload to local API: /player/volume Dec 29 17:56:28 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:28Z" level=debug msg="update volume requested to 35388/65535" Dec 29 17:56:28 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:28Z" level=debug msg="put connect state because VOLUME_CHANGED" Dec 29 17:56:28 volumio-lounge go-librespot[3267]: time="2025-12-29T17:56:28Z" level=trace msg="emitting websocket event: volume" Dec 29 17:56:28 volumio-lounge volumio[1287]: SPOTIFY: received: {"type":"volume","data":{"value":54,"max":100}} Dec 29 17:56:28 volumio-lounge volumio[1287]: SPOTIFY: RECEIVED SPOTIFY VOLUME 54 Dec 29 17:56:28 volumio-lounge volumio[1287]: SPOTIFY: received: {"type":"volume","data":{"value":54,"max":100}} Dec 29 17:56:28 volumio-lounge volumio[1287]: SPOTIFY: RECEIVED SPOTIFY VOLUME 54 Dec 29 17:56:29 volumio-lounge volumio[1287]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 29 17:56:29 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 29 17:56:29 volumio-lounge volumio[1287]: info: Creating Spotify config file Dec 29 17:56:29 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 17:56:29 volumio-lounge volumio[1287]: info: Spotify config file written Dec 29 17:56:29 volumio-lounge sudo[3292]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 29 17:56:29 volumio-lounge sudo[3292]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 17:56:29 volumio-lounge systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 29 17:56:29 volumio-lounge systemd[1]: go-librespot-daemon.service: Killing process 3273 (go-librespot) with signal SIGKILL. Dec 29 17:56:29 volumio-lounge systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 29 17:56:29 volumio-lounge volumio[1287]: info: Connection to go-librespot Websocket closed Dec 29 17:56:29 volumio-lounge systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 17:56:29 volumio-lounge volumio[1287]: info: Connection to go-librespot Websocket closed Dec 29 17:56:29 volumio-lounge systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 17:56:29 volumio-lounge go-librespot[3294]: go-librespot daemon starting... Dec 29 17:56:29 volumio-lounge sudo[3292]: pam_unix(sudo:session): session closed for user root Dec 29 17:56:30 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:30Z" level=info msg="running go-librespot 0.4.0" Dec 29 17:56:30 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:30Z" level=debug msg="app state loaded" Dec 29 17:56:30 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:30Z" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 17:56:30 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:30Z" 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-gae2.spotify.com:80]" Dec 29 17:56:30 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:30Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 29 17:56:30 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:30Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 29 17:56:30 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:30Z" level=info msg="zeroconf server listening on port 43771" Dec 29 17:56:30 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:30Z" level=debug msg="obtained new client token: AAB7ifV4TP94z2wv55FzCOTst/xGhHwp8J1WXsFYO1C21WQEX7ZmeQq+C1nufI+zLUZG9pEXeF+LYz8I34Kejs/T9LDWU7iVLlp7ctP7rGz5y25Vh31NIsQAoDwchEfacMrbEbKzGnCNqL3jsowA5wpVpdu95W3Meipr0IGjtuNrUdOsr3KU4dpFoZ55GfU7uzic8aQaZmi1WyXoskaB3CJNMsDFkOIhTxP16UcnbojLA977K2kc" Dec 29 17:56:30 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:30Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 29 17:56:30 volumio-lounge volumio[1287]: info: Getting Spotify volume Dec 29 17:56:30 volumio-lounge volumio[1287]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 29 17:56:30 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetState Dec 29 17:56:30 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:30Z" level=debug msg="completed keyexchange" Dec 29 17:56:30 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:30Z" level=debug msg="completed challenge" Dec 29 17:56:30 volumio-lounge volumio[1287]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Dec 29 17:56:30 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:30Z" level=info msg="authenticated AP" username="ld****on" Dec 29 17:56:30 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:30Z" level=info msg="authenticated Login5" username="ld****on" Dec 29 17:56:30 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:30Z" level=debug msg="initializing zeroconf session" username="ld****on" Dec 29 17:56:31 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 29 17:56:31 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:31Z" level=debug msg="dealer connection opened" Dec 29 17:56:31 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:31Z" level=trace msg="starting accesspoint recv loop" Dec 29 17:56:31 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:31Z" level=trace msg="starting dealer recv loop" Dec 29 17:56:31 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:31Z" level=trace msg="received accesspoint ping" Dec 29 17:56:31 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:31Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 29 17:56:31 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:31Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 29 17:56:31 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:31Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 29 17:56:31 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:31Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 29 17:56:31 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:31Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 29 17:56:31 volumio-lounge volumio[1287]: info: Spotify volume: 100 Dec 29 17:56:31 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:31Z" level=debug msg="received connection id: OTYwYzNhMGMtZGY5...ODcwMDRENzJGMw==" Dec 29 17:56:31 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:31Z" level=trace msg="received accesspoint pong ack" Dec 29 17:56:31 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:31Z" level=debug msg="put connect state because NEW_DEVICE" Dec 29 17:56:32 volumio-lounge volumio[1287]: info: Initializing connection to go-librespot Websocket Dec 29 17:56:32 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:32Z" level=debug msg="new websocket client" Dec 29 17:56:32 volumio-lounge volumio[1287]: info: Connection to go-librespot Websocket established Dec 29 17:56:32 volumio-lounge volumio[1287]: info: go-librespot daemon successfully initialized Dec 29 17:56:35 volumio-lounge volumio[1287]: info: Getting Spotify volume Dec 29 17:56:35 volumio-lounge volumio[1287]: info: Spotify volume: 100 Dec 29 17:56:35 volumio-lounge volumio[1287]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 29 17:56:35 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetState Dec 29 17:56:35 volumio-lounge volumio[1287]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Dec 29 17:56:35 volumio-lounge volumio[1287]: SPOTIFY: SPOTIFY VOLUME 100 Dec 29 17:56:35 volumio-lounge volumio[1287]: SPOTIFY: VOLUMIO VOLUME 54 Dec 29 17:56:35 volumio-lounge volumio[1287]: SPOTIFY: DELTA VOLUME ENOUGH: true Dec 29 17:56:35 volumio-lounge volumio[1287]: info: Setting Spotify Volume from Volumio: 54 Dec 29 17:56:35 volumio-lounge volumio[1287]: info: Initializing connection to go-librespot Websocket Dec 29 17:56:35 volumio-lounge volumio[1287]: info: Connection to go-librespot Websocket established Dec 29 17:56:35 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:35Z" level=debug msg="new websocket client" Dec 29 17:56:37 volumio-lounge volumio[1287]: SPOTIFY: SETTING SPOTIFY VOLUME 54 Dec 29 17:56:37 volumio-lounge volumio[1287]: info: Sending Spotify command with payload to local API: /player/volume Dec 29 17:56:37 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:37Z" level=debug msg="update volume requested to 35388/65535" Dec 29 17:56:37 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:37Z" level=debug msg="put connect state because VOLUME_CHANGED" Dec 29 17:56:37 volumio-lounge go-librespot[3295]: time="2025-12-29T17:56:37Z" level=trace msg="emitting websocket event: volume" Dec 29 17:56:37 volumio-lounge volumio[1287]: SPOTIFY: received: {"type":"volume","data":{"value":54,"max":100}} Dec 29 17:56:37 volumio-lounge volumio[1287]: SPOTIFY: RECEIVED SPOTIFY VOLUME 54 Dec 29 17:56:37 volumio-lounge volumio[1287]: SPOTIFY: received: {"type":"volume","data":{"value":54,"max":100}} Dec 29 17:56:37 volumio-lounge volumio[1287]: SPOTIFY: RECEIVED SPOTIFY VOLUME 54 Dec 29 17:56:38 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetState Dec 29 17:56:38 volumio-lounge volumio[1287]: info: Getting Spotify volume Dec 29 17:56:39 volumio-lounge volumio[1287]: info: Spotify volume: 54 Dec 29 17:56:39 volumio-lounge volumio[1287]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 29 17:56:39 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetState Dec 29 17:56:39 volumio-lounge volumio[1287]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Dec 29 17:56:39 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 29 17:56:39 volumio-lounge volumio[1287]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Dec 29 17:56:39 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Dec 29 17:56:39 volumio-lounge volumio[1287]: info: Received Get System Version Dec 29 17:56:39 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 17:56:39 volumio-lounge volumio[1287]: info: Received Get System Info Dec 29 17:56:39 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 29 17:56:39 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 29 17:56:39 volumio-lounge volumio[1287]: info: Discovery: Getting this device information Dec 29 17:56:39 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetState Dec 29 17:56:39 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 29 17:56:40 volumio-lounge volumio[1287]: info: Executing endpoint metavolumio Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 29 17:56:40 volumio-lounge volumio[1287]: info: Retrieving Cloud Streaming UI Dec 29 17:56:40 volumio-lounge volumio[1287]: info: Executing endpoint metavolumio Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 29 17:56:40 volumio-lounge volumio[1287]: info: Getting Tidal Cloud Configuration Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 29 17:56:40 volumio-lounge volumio[1287]: info: Getting Qobuz Cloud Configuration Dec 29 17:56:40 volumio-lounge volumio[1287]: info: Asking plugin for UI Config Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 29 17:56:40 volumio-lounge volumio[1287]: info: Getting Spotify Cloud Configuration Dec 29 17:56:40 volumio-lounge volumio[1287]: info: Asking plugin for UI Config Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 29 17:56:40 volumio-lounge volumio[1287]: info: Saving Spotify Acccount Dec 29 17:56:40 volumio-lounge volumio[1287]: info: Got it Dec 29 17:56:40 volumio-lounge volumio[1287]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Dec 29 17:56:40 volumio-lounge volumio[1287]: info: Got Tidal Cloud Configuration Dec 29 17:56:40 volumio-lounge volumio[1287]: info: Got it Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetBrowseSources Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetBrowseSources Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetBrowseSources Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 29 17:56:40 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Dec 29 17:56:44 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 29 17:56:46 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetState Dec 29 17:56:48 volumio-lounge volumio[1287]: info: Executing endpoint metavolumio Dec 29 17:56:48 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 29 17:56:48 volumio-lounge volumio[1287]: info: Executing endpoint metavolumio Dec 29 17:56:48 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 29 17:56:51 volumio-lounge volumio[1287]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 29 17:56:51 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Dec 29 17:56:51 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 17:56:51 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 29 17:56:51 volumio-lounge volumio[1287]: info: Getting Alsa Cards List without I2S DAC Dec 29 17:56:51 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SNumber Dec 29 17:56:51 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 17:56:51 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 17:56:51 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 17:56:51 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 17:56:51 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 17:56:51 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 17:56:51 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 17:56:51 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 17:56:51 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Dec 29 17:56:51 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Dec 29 17:57:01 volumio-lounge go-librespot[3295]: time="2025-12-29T17:57:01Z" level=trace msg="sent dealer ping" Dec 29 17:57:02 volumio-lounge go-librespot[3295]: time="2025-12-29T17:57:02Z" level=trace msg="received dealer pong" Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CALLMETHOD: audio_interface alsa_controller saveVolumeOptions [object Object] Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveVolumeOptions Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetState Dec 29 17:57:11 volumio-lounge volumio[1287]: info: Restoring Previous Volume level: 54 false true Dec 29 17:57:11 volumio-lounge volumio[1287]: info: VolumeController::SetAlsaVolume100 Dec 29 17:57:11 volumio-lounge volumio[1287]: info: Enable softmixer device for audio device number 2 Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioStop Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreStateMachine::stop Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreStateMachine::serviceStop Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreCommandRouter::serviceStop Dec 29 17:57:11 volumio-lounge volumio[1287]: info: [yt-cast-receiver] Player.stop() Dec 29 17:57:11 volumio-lounge volumio[1287]: info: Enable softmixer device for audio device undefined Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioUpdateVolumeSettings Dec 29 17:57:11 volumio-lounge volumio[1287]: info: Updating Volume Controller Parameters: Device: 2 Name: HiFiBerry DAC2 HD Mixer: Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Dec 29 17:57:11 volumio-lounge volumio[1287]: info: Disabling external Volume Control Dec 29 17:57:11 volumio-lounge volumio[1287]: info: Output device has changed, restarting MPD Dec 29 17:57:11 volumio-lounge volumio[1287]: info: Output device has changed, restarting Shairport Sync Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 17:57:11 volumio-lounge sudo[3392]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 29 17:57:11 volumio-lounge sudo[3392]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 17:57:11 volumio-lounge sudo[3392]: pam_unix(sudo:session): session closed for user root Dec 29 17:57:11 volumio-lounge sudo[3394]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 29 17:57:11 volumio-lounge sudo[3394]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 17:57:11 volumio-lounge volumio[1287]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 29 17:57:11 volumio-lounge volumio[1287]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 17:57:11 volumio-lounge systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 29 17:57:11 volumio-lounge volumio[1287]: info: QobuzConnect: setDeactiveState invoked Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetState Dec 29 17:57:11 volumio-lounge vtcs[2441]: [2025-12-29 17:57:11.554] [tisoc] [error] [SpkconServer.cpp:375] recv error. socket disconnected Dec 29 17:57:11 volumio-lounge vtcs[2441]: [2025-12-29 17:57:11.555] [tisoc] [warning] [SessionManagerImpl.cpp:240] Illegal State: IDLE Dec 29 17:57:11 volumio-lounge volumio[1287]: info: Volume configurations have been set Dec 29 17:57:11 volumio-lounge volumio[1287]: info: QobuzConnect: setDeactiveState invoked Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetState Dec 29 17:57:11 volumio-lounge sudo[3405]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Dec 29 17:57:11 volumio-lounge sudo[3405]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 17:57:11 volumio-lounge sudo[3407]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Dec 29 17:57:11 volumio-lounge sudo[3407]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 17:57:11 volumio-lounge systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... Dec 29 17:57:11 volumio-lounge systemd[1]: mpd.service: Deactivated successfully. Dec 29 17:57:11 volumio-lounge systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 29 17:57:11 volumio-lounge systemd[1]: mpd.service: Consumed 5.846s CPU time. Dec 29 17:57:11 volumio-lounge systemd[1]: vtcs.service: Killing process 2448 (vtcs) with signal SIGKILL. Dec 29 17:57:11 volumio-lounge systemd[1]: vtcs.service: Deactivated successfully. Dec 29 17:57:11 volumio-lounge systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioUpdateVolumeSettings Dec 29 17:57:11 volumio-lounge volumio[1287]: info: Updating Volume Controller Parameters: Device: 2 Name: HiFiBerry DAC2 HD Mixer: Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Dec 29 17:57:11 volumio-lounge volumio[1287]: info: Disabling external Volume Control Dec 29 17:57:11 volumio-lounge sudo[3405]: pam_unix(sudo:session): session closed for user root Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 29 17:57:11 volumio-lounge systemd[1]: mpd.socket: Deactivated successfully. Dec 29 17:57:11 volumio-lounge systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 29 17:57:11 volumio-lounge systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetState Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreStateMachine::pushState Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioPushState Dec 29 17:57:11 volumio-lounge volumio[1287]: info: MRS: Pushing multiroomSync output update for this device Dec 29 17:57:11 volumio-lounge volumio[1287]: info: MRS: Pushing multiroomSync output Dec 29 17:57:11 volumio-lounge volumio[1287]: info: CoreCommandRouter::volumioGetState Dec 29 17:57:11 volumio-lounge systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 29 17:57:11 volumio-lounge sudo[3423]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Dec 29 17:57:11 volumio-lounge sudo[3423]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 17:57:11 volumio-lounge systemd[1]: Starting mpd.service - Music Player Daemon... Dec 29 17:57:11 volumio-lounge sudo[3425]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Dec 29 17:57:11 volumio-lounge sudo[3425]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 17:57:11 volumio-lounge sudo[3407]: pam_unix(sudo:session): session closed for user root Dec 29 17:57:11 volumio-lounge sudo[3435]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Dec 29 17:57:11 volumio-lounge sudo[3435]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 17:57:11 volumio-lounge volumio[1287]: error: [ytcr] MPD error: Dec 29 17:57:11 volumio-lounge volumio[1287]: (AssertionError) The expression evaluated to a falsy value: Dec 29 17:57:11 volumio-lounge volumio[1287]: assert.ok(this.idling) Dec 29 17:57:11 volumio-lounge volumio[1287]: AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value: Dec 29 17:57:11 volumio-lounge volumio[1287]: assert.ok(this.idling) Dec 29 17:57:11 volumio-lounge volumio[1287]: at MPDClient.sendCommand (/data/plugins/music_service/ytcr/node_modules/mpd2/lib/index.js:62:12) Dec 29 17:57:11 volumio-lounge volumio[1287]: at MPDPlayer. (/data/plugins/music_service/ytcr/node_modules/mpd-api/lib/api/index.js:60:16) Dec 29 17:57:11 volumio-lounge volumio[1287]: at /data/plugins/music_service/ytcr/dist/lib/MPDPlayer.js:290:13 Dec 29 17:57:11 volumio-lounge volumio[1287]: at new Promise () Dec 29 17:57:11 volumio-lounge volumio[1287]: at MPDPlayer.resolveOnMPDStatusChanged (/data/plugins/music_service/ytcr/dist/lib/MPDPlayer.js:269:16) Dec 29 17:57:11 volumio-lounge volumio[1287]: at MPDPlayer.doStop (/data/plugins/music_service/ytcr/dist/lib/MPDPlayer.js:158:37) Dec 29 17:57:11 volumio-lounge volumio[1287]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Dec 29 17:57:11 volumio-lounge volumio[1287]: at async MPDPlayer.stop (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/lib/Player.js:121:24) Dec 29 17:57:11 volumio-lounge volumio[1287]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 29 17:57:11 volumio-lounge volumio[1287]: MPDError: Not connected Dec 29 17:57:11 volumio-lounge volumio[1287]: at MPDClient.send (/data/plugins/music_service/ytcr/node_modules/mpd2/lib/index.js:101:13) Dec 29 17:57:11 volumio-lounge volumio[1287]: at MPDClient.sendCommand (/data/plugins/music_service/ytcr/node_modules/mpd2/lib/index.js:65:10) Dec 29 17:57:11 volumio-lounge volumio[1287]: at Object.get (/data/plugins/music_service/ytcr/node_modules/mpd-api/lib/api/index.js:60:16) Dec 29 17:57:11 volumio-lounge volumio[1287]: at MPDPlayer.getVolumioState (/data/plugins/music_service/ytcr/dist/lib/MPDPlayer.js:297:100) Dec 29 17:57:11 volumio-lounge volumio[1287]: at ControllerYTCR.pushState (/data/plugins/music_service/ytcr/dist/index.js:566:104) Dec 29 17:57:11 volumio-lounge volumio[1287]: at /data/plugins/music_service/ytcr/dist/index.js:308:28 Dec 29 17:57:11 volumio-lounge volumio[1287]: at CoreCommandRouter.callCallback (/volumio/app/index.js:214:9) Dec 29 17:57:11 volumio-lounge volumio[1287]: at CoreCommandRouter.volumioupdatevolume (/volumio/app/index.js:143:8) Dec 29 17:57:11 volumio-lounge volumio[1287]: at Promise._successFn (/volumio/app/index.js:137:16) Dec 29 17:57:11 volumio-lounge volumio[1287]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Dec 29 17:57:11 volumio-lounge volumio[1287]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) { Dec 29 17:57:11 volumio-lounge volumio[1287]: code: 'ENOTCONNECTED' Dec 29 17:57:11 volumio-lounge volumio[1287]: } Dec 29 17:57:11 volumio-lounge volumio[1287]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 29 17:57:11 volumio-lounge sudo[3442]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Dec 29 17:57:11 volumio-lounge sudo[3442]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 17:57:11 volumio-lounge sudo[3423]: pam_unix(sudo:session): session closed for user root Dec 29 17:57:11 volumio-lounge sudo[3425]: pam_unix(sudo:session): session closed for user root Dec 29 17:57:11 volumio-lounge sudo[3435]: pam_unix(sudo:session): session closed for user root Dec 29 17:57:11 volumio-lounge sudo[3427]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 29 17:57:11 volumio-lounge sudo[3442]: pam_unix(sudo:session): session closed for user root Dec 29 17:57:11 volumio-lounge sudo[3427]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 29 17:57:11 volumio-lounge sudo[3427]: pam_unix(sudo:session): session closed for user root Dec 29 17:57:11 volumio-lounge sudo[3458]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Dec 29 17:57:11 volumio-lounge sudo[3458]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 17:57:11 volumio-lounge sudo[3459]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Dec 29 17:57:11 volumio-lounge sudo[3459]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 17:57:11 volumio-lounge qobuz-connect[2411]: 20251229 17:57:11.993 [2411.2411] INFO SampleApp: Stopping Local configuration server Dec 29 17:57:11 volumio-lounge systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Dec 29 17:57:12 volumio-lounge sudo[3466]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-29 17:56' Dec 29 17:57:12 volumio-lounge sudo[3466]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"