-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Fri 2025-07-18 17:32:39 CEST. -- Jul 18 17:31:02 volumio volumio[909]: info: Initializing connection to go-librespot Websocket Jul 18 17:31:02 volumio go-librespot[20501]: time="2025-07-18T17:31:02+02:00" level=debug msg="new websocket client" Jul 18 17:31:02 volumio volumio[909]: info: Connection to go-librespot Websocket established Jul 18 17:31:05 volumio volumio[909]: info: Getting Spotify volume Jul 18 17:31:05 volumio volumio[909]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Jul 18 17:31:05 volumio volumio[909]: info: CoreCommandRouter::volumioGetState Jul 18 17:31:05 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 18 17:31:05 volumio volumio[909]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jul 18 17:31:05 volumio volumio[909]: SPOTIFY: SPOTIFY VOLUME undefined Jul 18 17:31:05 volumio volumio[909]: SPOTIFY: VOLUMIO VOLUME 86 Jul 18 17:31:05 volumio volumio[909]: info: Aligning Spotify Volume to Volumio Volume Jul 18 17:31:05 volumio volumio[909]: info: CoreCommandRouter::volumioGetState Jul 18 17:31:05 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 18 17:31:05 volumio volumio[909]: info: Setting Spotify Volume from Volumio: 86 Jul 18 17:31:07 volumio volumio[909]: SPOTIFY: SETTING SPOTIFY VOLUME 86 Jul 18 17:31:07 volumio volumio[909]: info: Sending Spotify command with payload to local API: /player/volume Jul 18 17:31:23 volumio volumio[909]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 18 17:32:07 volumio volumio[909]: info: Received OAUTH Data Jul 18 17:32:07 volumio volumio[909]: info: Executing Spotify Oauth Login Jul 18 17:32:07 volumio volumio[909]: info: Saving Spotify Refresh Token Jul 18 17:32:08 volumio volumio[909]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 18 17:32:08 volumio volumio[909]: SPOTIFY: BQCu4UG8f3JDHF6wpl4VUdyycVDnqsqvxYs2PNWf4W3P7iO1pq-HmeyzXseunCCcH7CrhtkT38UoYUxr5Yo_pgFHrEJQ6MH8DWC2KyEFDq1hks9tIJBNOn0MSum4SIpLp2e4FNu7YgjzmLbH5m1lT8KGZ8EuzuOUC-YvxiEHw6xGSJrP6GesmXDvKWyBEdSWITz1dsL5_vdiqN92eqjGc8jCdRaiAQe99M85lVt0HgPNSWZ-q-DIC0Z3im4NaZt0su3-FA0zg-4vOoNE-uxMo6xWeuZ7Fmsoj_KHRaKCbiYfivETVjOBvKUbAG-VfvGErqqDuuTL0soGr2JWhvvH3vkxsIRlkyrEqK2lyLlx Jul 18 17:32:08 volumio volumio[909]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 18 17:32:08 volumio volumio[909]: info: New Spotify access token = BQCu4UG8f3JDHF6wpl4VUdyycVDnqsqvxYs2PNWf4W3P7iO1pq-HmeyzXseunCCcH7CrhtkT38UoYUxr5Yo_pgFHrEJQ6MH8DWC2KyEFDq1hks9tIJBNOn0MSum4SIpLp2e4FNu7YgjzmLbH5m1lT8KGZ8EuzuOUC-YvxiEHw6xGSJrP6GesmXDvKWyBEdSWITz1dsL5_vdiqN92eqjGc8jCdRaiAQe99M85lVt0HgPNSWZ-q-DIC0Z3im4NaZt0su3-FA0zg-4vOoNE-uxMo6xWeuZ7Fmsoj_KHRaKCbiYfivETVjOBvKUbAG-VfvGErqqDuuTL0soGr2JWhvvH3vkxsIRlkyrEqK2lyLlx Jul 18 17:32:08 volumio volumio[909]: info: Spotify credentials grant success - running version from March 24, 2019 Jul 18 17:32:08 volumio volumio[909]: SPOTIFY: User informations: {"country":"IT","display_name":"Makoz","email":"makozoe@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/1180921654"},"followers":{"href":null,"total":12},"href":"https://api.spotify.com/v1/users/1180921654","id":"1180921654","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85d79920e866b902d5805a0d39","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82d79920e866b902d5805a0d39","width":64}],"product":"premium","type":"user","uri":"spotify:user:1180921654"} Jul 18 17:32:08 volumio volumio[909]: info: Creating Spotify config file Jul 18 17:32:08 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 18 17:32:08 volumio volumio[909]: info: Spotify config file written Jul 18 17:32:08 volumio sudo[20684]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 18 17:32:08 volumio sudo[20684]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 18 17:32:08 volumio systemd[1]: Stopping go-librespot Daemon... Jul 18 17:32:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Jul 18 17:32:08 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Jul 18 17:32:08 volumio systemd[1]: Stopped go-librespot Daemon. Jul 18 17:32:08 volumio volumio[909]: ------------------------------------ BT MESSAGE: BT STATUS: running Jul 18 17:32:08 volumio volumio[909]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Jul 18 17:32:08 volumio volumio[909]: info: Connection to go-librespot Websocket closed Jul 18 17:32:08 volumio systemd[1]: Started go-librespot Daemon. Jul 18 17:32:08 volumio go-librespot[20687]: go-librespot daemon starting... Jul 18 17:32:08 volumio sudo[20684]: pam_unix(sudo:session): session closed for user root Jul 18 17:32:08 volumio go-librespot[20687]: time="2025-07-18T17:32:08+02:00" level=info msg="running go-librespot 0.2.0" Jul 18 17:32:08 volumio go-librespot[20687]: time="2025-07-18T17:32:08+02:00" level=debug msg="app state loaded" Jul 18 17:32:08 volumio go-librespot[20687]: time="2025-07-18T17:32:08+02:00" level=debug msg="stored credentials not found" Jul 18 17:32:08 volumio go-librespot[20687]: time="2025-07-18T17:32:08+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 18 17:32:08 volumio volumio[909]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 18 17:32:08 volumio volumio[909]: SPOTIFY: BQCmo4FKyfGBRmFNvX62dLthwo-1X_h6cCJVh1RbBZaIZlnwZLexASmxRwqmR_i-Oj3zFuI2Xt-O5y6tuzxXlS1-RebpBzxtBu4FbQcjwpQOW-n0SQoV3idmcZjcuxysE6spXPZp-IHN01eLNTHxzlONyY-t2jD7-tdVw0LLB-upZSaP1BuNKkzFFXoqTd62dKbNTJ-1hIZnw2NyCuslxaKPrr_jE6oTk8kuMgv3QftEiRIVLvc1bmwFCmNndTrn3T7GqFf6GpMO3u6tDPsyAJET21msd7wPiXLCkqp7ZuitPugwlHkCuVdlDwMXHNIs_DUvf95QJgx1mGHqSj1tNhRDRG87Kc-adPVmZtrU Jul 18 17:32:08 volumio volumio[909]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 18 17:32:08 volumio volumio[909]: info: New Spotify access token = BQCmo4FKyfGBRmFNvX62dLthwo-1X_h6cCJVh1RbBZaIZlnwZLexASmxRwqmR_i-Oj3zFuI2Xt-O5y6tuzxXlS1-RebpBzxtBu4FbQcjwpQOW-n0SQoV3idmcZjcuxysE6spXPZp-IHN01eLNTHxzlONyY-t2jD7-tdVw0LLB-upZSaP1BuNKkzFFXoqTd62dKbNTJ-1hIZnw2NyCuslxaKPrr_jE6oTk8kuMgv3QftEiRIVLvc1bmwFCmNndTrn3T7GqFf6GpMO3u6tDPsyAJET21msd7wPiXLCkqp7ZuitPugwlHkCuVdlDwMXHNIs_DUvf95QJgx1mGHqSj1tNhRDRG87Kc-adPVmZtrU Jul 18 17:32:08 volumio volumio[909]: info: Spotify credentials grant success - running version from March 24, 2019 Jul 18 17:32:08 volumio volumio[909]: SPOTIFY: User informations: {"country":"IT","display_name":"Makoz","email":"makozoe@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/1180921654"},"followers":{"href":null,"total":12},"href":"https://api.spotify.com/v1/users/1180921654","id":"1180921654","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85d79920e866b902d5805a0d39","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82d79920e866b902d5805a0d39","width":64}],"product":"premium","type":"user","uri":"spotify:user:1180921654"} Jul 18 17:32:08 volumio volumio[909]: info: Spotify Successfully logged in Jul 18 17:32:08 volumio volumio[909]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 18 17:32:08 volumio volumio[909]: info: [1752852728707] CoreMusicLibrary::Adding element Spotify Jul 18 17:32:08 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 18 17:32:08 volumio volumio[909]: Cannot find translation for source Spotify Jul 18 17:32:08 volumio go-librespot[20687]: time="2025-07-18T17:32:08+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 18 17:32:08 volumio go-librespot[20687]: time="2025-07-18T17:32:08+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jul 18 17:32:08 volumio go-librespot[20687]: time="2025-07-18T17:32:08+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jul 18 17:32:08 volumio go-librespot[20687]: time="2025-07-18T17:32:08+02:00" level=info msg="zeroconf server listening on port 33099" Jul 18 17:32:08 volumio go-librespot[20687]: time="2025-07-18T17:32:08+02:00" level=debug msg="obtained new client token: AAB1xoLIVPW3svKiK8o+G4H+PdWFyhNAOcjqFG7mOh90g9W52USuPAFEtXqGgtzV1KugFBmGShDsaO35MgMECOYo6//DF+wCPJOjgRfeIEA8El8M2noeHeSknRwpUbvxNCtWnmYGSxPpQ0NZtWoOGbLvjDwKU9D5iNrkkK3Xqm21joEtNy/bP+jnUWK6S5OI5fFDuzWuMcQdOYSi5zfSO3EjnYwjpCcm4QHZAZy1Y2nJud2sJyCyKRBU" Jul 18 17:32:08 volumio sudo[20696]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 18 17:32:08 volumio sudo[20696]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 18 17:32:08 volumio sudo[20696]: pam_unix(sudo:session): session closed for user root Jul 18 17:32:08 volumio go-librespot[20687]: time="2025-07-18T17:32:08+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 18 17:32:08 volumio sudo[20699]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 18 17:32:08 volumio sudo[20699]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 18 17:32:08 volumio sudo[20699]: pam_unix(sudo:session): session closed for user root Jul 18 17:32:08 volumio go-librespot[20687]: time="2025-07-18T17:32:08+02:00" level=debug msg="completed keyexchange" Jul 18 17:32:08 volumio go-librespot[20687]: time="2025-07-18T17:32:08+02:00" level=debug msg="completed challenge" Jul 18 17:32:09 volumio go-librespot[20687]: time="2025-07-18T17:32:09+02:00" level=info msg="authenticated AP as 1180921654" Jul 18 17:32:09 volumio volumio[909]: verbose: New Socket.io Connection to 192.168.1.210 from 192.168.1.185 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/138.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Jul 18 17:32:09 volumio go-librespot[20687]: time="2025-07-18T17:32:09+02:00" level=info msg="authenticated Login5 as 1180921654" Jul 18 17:32:09 volumio go-librespot[20687]: time="2025-07-18T17:32:09+02:00" level=debug msg="stored credentials for 1180921654" Jul 18 17:32:09 volumio go-librespot[20687]: time="2025-07-18T17:32:09+02:00" level=debug msg="initializing zeroconf session, username: 1180921654" Jul 18 17:32:09 volumio go-librespot[20687]: time="2025-07-18T17:32:09+02:00" level=debug msg="dealer connection opened" Jul 18 17:32:09 volumio go-librespot[20687]: time="2025-07-18T17:32:09+02:00" level=trace msg="starting accesspoint recv loop" Jul 18 17:32:09 volumio go-librespot[20687]: time="2025-07-18T17:32:09+02:00" level=trace msg="starting dealer recv loop" Jul 18 17:32:09 volumio go-librespot[20687]: time="2025-07-18T17:32:09+02:00" level=trace msg="received accesspoint ping" Jul 18 17:32:09 volumio go-librespot[20687]: time="2025-07-18T17:32:09+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 18 17:32:09 volumio go-librespot[20687]: time="2025-07-18T17:32:09+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 18 17:32:09 volumio go-librespot[20687]: time="2025-07-18T17:32:09+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 18 17:32:09 volumio go-librespot[20687]: time="2025-07-18T17:32:09+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 18 17:32:09 volumio go-librespot[20687]: time="2025-07-18T17:32:09+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 18 17:32:09 volumio go-librespot[20687]: time="2025-07-18T17:32:09+02:00" level=debug msg="received connection id: Mzg4YWVjYzctNmQxMi00NDk3LWFkMWQtMTI3N2EzM2RkYTY5K2RlYWxlcit0Y3A6Ly8wYWIxNTFlYy5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQzk4NjZBNTcxRTlGNTAzRUFBOTE2RjdBRDRGNERENzFGNjdGRkJBOEJFMEI0MzdBMDBGNzVBODU0RjBDRTk0Mg==" Jul 18 17:32:09 volumio go-librespot[20687]: time="2025-07-18T17:32:09+02:00" level=trace msg="received accesspoint pong ack" Jul 18 17:32:09 volumio go-librespot[20687]: time="2025-07-18T17:32:09+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 18 17:32:09 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jul 18 17:32:09 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jul 18 17:32:10 volumio volumio[909]: info: CoreCommandRouter::volumioGetVisibleSources Jul 18 17:32:10 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 18 17:32:10 volumio volumio[909]: info: CoreCommandRouter::volumioGetState Jul 18 17:32:10 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 18 17:32:10 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jul 18 17:32:10 volumio volumio[909]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 18 17:32:10 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jul 18 17:32:10 volumio volumio[909]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Jul 18 17:32:10 volumio volumio[909]: info: Received Get System Info Jul 18 17:32:10 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 18 17:32:10 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 18 17:32:10 volumio volumio[909]: info: Discovery: Getting this device information Jul 18 17:32:10 volumio volumio[909]: info: CoreCommandRouter::volumioGetState Jul 18 17:32:10 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 18 17:32:10 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 18 17:32:10 volumio volumio[909]: info: CoreCommandRouter::volumioGetState Jul 18 17:32:10 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 18 17:32:10 volumio volumio[909]: info: Listing playlists Jul 18 17:32:10 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jul 18 17:32:10 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jul 18 17:32:10 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jul 18 17:32:10 volumio volumio[909]: info: Received Get System Info Jul 18 17:32:10 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 18 17:32:10 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 18 17:32:10 volumio volumio[909]: info: Discovery: Getting this device information Jul 18 17:32:10 volumio volumio[909]: info: CoreCommandRouter::volumioGetState Jul 18 17:32:10 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 18 17:32:10 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 18 17:32:11 volumio volumio[909]: info: Initializing connection to go-librespot Websocket Jul 18 17:32:11 volumio go-librespot[20687]: time="2025-07-18T17:32:11+02:00" level=debug msg="new websocket client" Jul 18 17:32:11 volumio volumio[909]: info: Connection to go-librespot Websocket established Jul 18 17:32:11 volumio volumio[909]: info: go-librespot daemon successfully initialized Jul 18 17:32:11 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jul 18 17:32:12 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jul 18 17:32:12 volumio volumio[909]: info: Received Get System Info Jul 18 17:32:12 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 18 17:32:12 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 18 17:32:12 volumio volumio[909]: info: Discovery: Getting this device information Jul 18 17:32:12 volumio volumio[909]: info: CoreCommandRouter::volumioGetState Jul 18 17:32:12 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 18 17:32:12 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 18 17:32:14 volumio volumio[909]: info: Getting Spotify volume Jul 18 17:32:14 volumio volumio[909]: info: Spotify volume: 100 Jul 18 17:32:14 volumio volumio[909]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Jul 18 17:32:14 volumio volumio[909]: info: CoreCommandRouter::volumioGetState Jul 18 17:32:14 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 18 17:32:14 volumio volumio[909]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jul 18 17:32:14 volumio volumio[909]: SPOTIFY: SPOTIFY VOLUME 100 Jul 18 17:32:14 volumio volumio[909]: SPOTIFY: VOLUMIO VOLUME 86 Jul 18 17:32:14 volumio volumio[909]: SPOTIFY: DELTA VOLUME ENOUGH: true Jul 18 17:32:14 volumio volumio[909]: info: Setting Spotify Volume from Volumio: 86 Jul 18 17:32:14 volumio volumio[909]: info: Initializing connection to go-librespot Websocket Jul 18 17:32:14 volumio go-librespot[20687]: time="2025-07-18T17:32:14+02:00" level=debug msg="new websocket client" Jul 18 17:32:14 volumio volumio[909]: info: Connection to go-librespot Websocket established Jul 18 17:32:16 volumio volumio[909]: SPOTIFY: SETTING SPOTIFY VOLUME 86 Jul 18 17:32:16 volumio volumio[909]: info: Sending Spotify command with payload to local API: /player/volume Jul 18 17:32:16 volumio go-librespot[20687]: time="2025-07-18T17:32:16+02:00" level=debug msg="update volume to 56360/65535" Jul 18 17:32:17 volumio go-librespot[20687]: time="2025-07-18T17:32:17+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jul 18 17:32:17 volumio go-librespot[20687]: time="2025-07-18T17:32:17+02:00" level=trace msg="emitting websocket event: volume" Jul 18 17:32:17 volumio volumio[909]: SPOTIFY: received: {"type":"volume","data":{"value":86,"max":100}} Jul 18 17:32:17 volumio volumio[909]: SPOTIFY: RECEIVED SPOTIFY VOLUME 86 Jul 18 17:32:17 volumio volumio[909]: SPOTIFY: received: {"type":"volume","data":{"value":86,"max":100}} Jul 18 17:32:17 volumio volumio[909]: SPOTIFY: RECEIVED SPOTIFY VOLUME 86 Jul 18 17:32:17 volumio volumio[909]: info: Getting Spotify volume Jul 18 17:32:17 volumio volumio[909]: info: Spotify volume: 86 Jul 18 17:32:17 volumio volumio[909]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Jul 18 17:32:17 volumio volumio[909]: info: CoreCommandRouter::volumioGetState Jul 18 17:32:17 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 18 17:32:17 volumio volumio[909]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jul 18 17:32:18 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jul 18 17:32:19 volumio volumio[909]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jul 18 17:32:19 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jul 18 17:32:19 volumio volumio[909]: info: Creating Spotify config file Jul 18 17:32:19 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 18 17:32:19 volumio volumio[909]: info: Spotify config file written Jul 18 17:32:19 volumio sudo[20721]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 18 17:32:19 volumio sudo[20721]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 18 17:32:19 volumio systemd[1]: Stopping go-librespot Daemon... Jul 18 17:32:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Jul 18 17:32:19 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Jul 18 17:32:19 volumio systemd[1]: Stopped go-librespot Daemon. Jul 18 17:32:19 volumio volumio[909]: ------------------------------------ BT MESSAGE: BT STATUS: running Jul 18 17:32:19 volumio volumio[909]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Jul 18 17:32:19 volumio volumio[909]: info: Connection to go-librespot Websocket closed Jul 18 17:32:19 volumio volumio[909]: info: Connection to go-librespot Websocket closed Jul 18 17:32:19 volumio systemd[1]: Started go-librespot Daemon. Jul 18 17:32:19 volumio go-librespot[20725]: go-librespot daemon starting... Jul 18 17:32:19 volumio sudo[20721]: pam_unix(sudo:session): session closed for user root Jul 18 17:32:19 volumio go-librespot[20725]: time="2025-07-18T17:32:19+02:00" level=info msg="running go-librespot 0.2.0" Jul 18 17:32:19 volumio go-librespot[20725]: time="2025-07-18T17:32:19+02:00" level=debug msg="app state loaded" Jul 18 17:32:19 volumio go-librespot[20725]: time="2025-07-18T17:32:19+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=info msg="zeroconf server listening on port 33371" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=debug msg="obtained new client token: AAAZLANanGi3IOIO+ByMg9wwnfU4vW+MKWrkfNBOCcxdAcFY92MmWisuQO5CgJ6Yg+QdSyS5LBRQBLe6CG7RYou5+N/ewZW8o+Eomq3NGZGBw7O1LCyvqCGrtX7/PtT6ZSLE2GlC48cwM0wkYsm3ZO4lanwaq4Hj1O8ZTWO0HgwGjBfG1M0IgXWUCNBHNoyT1pAzvD5cT3WvcppJ/6lBvk8RHWJ0w/fZhIVY42F+TqK/rl1zO6w4cg==" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=debug msg="completed keyexchange" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=debug msg="completed challenge" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=info msg="authenticated AP as 1180921654" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=info msg="authenticated Login5 as 1180921654" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=debug msg="initializing zeroconf session, username: 1180921654" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=debug msg="dealer connection opened" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=trace msg="starting accesspoint recv loop" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=trace msg="starting dealer recv loop" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=trace msg="received accesspoint ping" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=debug msg="received connection id: ZWZiYzkwZWMtZTc5MC00YjFjLWFmNWEtODA4MzI4YTBhYTI5K2RlYWxlcit0Y3A6Ly8wYWIxNTA5YS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArRDg2RDg0NEEwREQ5MzAzMzRDMTRERjZCRjdCNERFNTQwMzY5RDg2NTFDQ0UxMkZCOTg5NTU5OTFGMTQwQUZCOQ==" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=trace msg="received accesspoint pong ack" Jul 18 17:32:20 volumio go-librespot[20725]: time="2025-07-18T17:32:20+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 18 17:32:22 volumio volumio[909]: info: Initializing connection to go-librespot Websocket Jul 18 17:32:22 volumio go-librespot[20725]: time="2025-07-18T17:32:22+02:00" level=debug msg="new websocket client" Jul 18 17:32:22 volumio volumio[909]: info: Connection to go-librespot Websocket established Jul 18 17:32:22 volumio volumio[909]: info: go-librespot daemon successfully initialized Jul 18 17:32:25 volumio volumio[909]: info: CoreCommandRouter::volumioGetState Jul 18 17:32:25 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 18 17:32:25 volumio volumio[909]: info: Getting Spotify volume Jul 18 17:32:25 volumio volumio[909]: info: Spotify volume: 100 Jul 18 17:32:25 volumio volumio[909]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Jul 18 17:32:25 volumio volumio[909]: info: CoreCommandRouter::volumioGetState Jul 18 17:32:25 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 18 17:32:25 volumio volumio[909]: info: Initializing connection to go-librespot Websocket Jul 18 17:32:25 volumio volumio[909]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jul 18 17:32:25 volumio volumio[909]: SPOTIFY: SPOTIFY VOLUME 100 Jul 18 17:32:25 volumio volumio[909]: SPOTIFY: VOLUMIO VOLUME 86 Jul 18 17:32:25 volumio volumio[909]: SPOTIFY: DELTA VOLUME ENOUGH: true Jul 18 17:32:25 volumio volumio[909]: info: Setting Spotify Volume from Volumio: 86 Jul 18 17:32:25 volumio go-librespot[20725]: time="2025-07-18T17:32:25+02:00" level=debug msg="new websocket client" Jul 18 17:32:25 volumio volumio[909]: info: Connection to go-librespot Websocket established Jul 18 17:32:26 volumio volumio[909]: info: CoreCommandRouter::volumioPlay Jul 18 17:32:26 volumio volumio[909]: info: CoreStateMachine::play index undefined Jul 18 17:32:26 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 18 17:32:26 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 18 17:32:27 volumio volumio[909]: SPOTIFY: SETTING SPOTIFY VOLUME 86 Jul 18 17:32:27 volumio volumio[909]: info: Sending Spotify command with payload to local API: /player/volume Jul 18 17:32:27 volumio go-librespot[20725]: time="2025-07-18T17:32:27+02:00" level=debug msg="update volume to 56360/65535" Jul 18 17:32:28 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jul 18 17:32:28 volumio volumio[909]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jul 18 17:32:28 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jul 18 17:32:28 volumio volumio[909]: info: Received Get System Version Jul 18 17:32:28 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 18 17:32:28 volumio volumio[909]: info: Received Get System Info Jul 18 17:32:28 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 18 17:32:28 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 18 17:32:28 volumio volumio[909]: info: Discovery: Getting this device information Jul 18 17:32:28 volumio volumio[909]: info: CoreCommandRouter::volumioGetState Jul 18 17:32:28 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 18 17:32:28 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 18 17:32:28 volumio go-librespot[20725]: time="2025-07-18T17:32:28+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jul 18 17:32:28 volumio go-librespot[20725]: time="2025-07-18T17:32:28+02:00" level=trace msg="emitting websocket event: volume" Jul 18 17:32:28 volumio volumio[909]: SPOTIFY: received: {"type":"volume","data":{"value":86,"max":100}} Jul 18 17:32:28 volumio volumio[909]: SPOTIFY: RECEIVED SPOTIFY VOLUME 86 Jul 18 17:32:28 volumio volumio[909]: SPOTIFY: received: {"type":"volume","data":{"value":86,"max":100}} Jul 18 17:32:28 volumio volumio[909]: SPOTIFY: RECEIVED SPOTIFY VOLUME 86 Jul 18 17:32:28 volumio volumio[909]: info: Getting Spotify volume Jul 18 17:32:28 volumio volumio[909]: info: Spotify volume: 86 Jul 18 17:32:28 volumio volumio[909]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Jul 18 17:32:29 volumio volumio[909]: info: CoreCommandRouter::volumioGetState Jul 18 17:32:29 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 18 17:32:29 volumio volumio[909]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 18 17:32:31 volumio volumio[909]: info: Retrieving Cloud Streaming UI Jul 18 17:32:31 volumio volumio[909]: info: Getting Tidal Cloud Configuration Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 18 17:32:31 volumio volumio[909]: info: Getting Qobuz Cloud Configuration Jul 18 17:32:31 volumio volumio[909]: info: Asking plugin for UI Config Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 18 17:32:31 volumio volumio[909]: info: Getting Spotify Cloud Configuration Jul 18 17:32:31 volumio volumio[909]: info: Asking plugin for UI Config Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 18 17:32:31 volumio volumio[909]: info: Saving Spotify Acccount Jul 18 17:32:31 volumio volumio[909]: info: Got it Jul 18 17:32:31 volumio volumio[909]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Jul 18 17:32:31 volumio volumio[909]: info: Got Tidal Cloud Configuration Jul 18 17:32:31 volumio volumio[909]: info: Got it Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::volumioGetBrowseSources Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::volumioGetBrowseSources Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::volumioGetBrowseSources Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jul 18 17:32:31 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Jul 18 17:32:34 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: networkfs , discoverShares Jul 18 17:32:34 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , browseForService Jul 18 17:32:35 volumio volumio[909]: info: Executing SMB command: smbclient --no-pass --debuglevel=0 -L zoe.local. Jul 18 17:32:35 volumio volumio[909]: info: Executing SMB command: smbclient --no-pass --debuglevel=0 -L volumio.local. Jul 18 17:32:35 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jul 18 17:32:39 volumio volumio[909]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 18 17:32:39 volumio volumio[909]: Error: dns service error: unknown Jul 18 17:32:39 volumio volumio[909]: at MDNSService.on_resolver_done (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:19:30) Jul 18 17:32:39 volumio volumio[909]: at SocketWatcher.MDNSService.self.watcher.callback (/volumio/node_modules/mdns/lib/mdns_service.js:18:40) { Jul 18 17:32:39 volumio volumio[909]: errorCode: -65537 Jul 18 17:32:39 volumio volumio[909]: } Jul 18 17:32:39 volumio volumio[909]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 18 17:32:39 volumio sudo[20852]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-07-18 17:31 Jul 18 17:32:39 volumio sudo[20852]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="a142ed2648fb91920de0dde3a60cd39b5d0ba4f6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="811ff8312d42f9da0260be1d353081a805678820" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 02 Jul 2025 04:07:25 PM CEST" VOLUMIO_VERSION="3.819" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3b9115b1943141a9d7186aa434f8f3c2"