-- Logs begin at Sat 2024-10-05 16:03:31 PDT, end at Sun 2024-10-06 11:26:11 PDT. -- Oct 06 11:25:23 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 06 11:25:23 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 06 11:25:23 mcfvolumio volumio[900]: info: Discovery: Getting this device information Oct 06 11:25:23 mcfvolumio volumio[900]: info: CoreCommandRouter::volumioGetState Oct 06 11:25:23 mcfvolumio volumio[900]: info: CorePlayQueue::getTrack 0 Oct 06 11:25:23 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 06 11:25:24 mcfvolumio volumio[900]: info: Received OAUTH Data Oct 06 11:25:24 mcfvolumio volumio[900]: info: Executing Spotify Oauth Login Oct 06 11:25:24 mcfvolumio volumio[900]: info: Saving Spotify Refresh Token Oct 06 11:25:24 mcfvolumio sudo[10433]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 06 11:25:24 mcfvolumio sudo[10433]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 11:25:24 mcfvolumio sudo[10433]: pam_unix(sudo:session): session closed for user root Oct 06 11:25:24 mcfvolumio sudo[10436]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 06 11:25:24 mcfvolumio sudo[10436]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 11:25:24 mcfvolumio volumio[900]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 06 11:25:24 mcfvolumio volumio[900]: SPOTIFY: BQDqTbO2ygarUmiuuZgcyR1mryT6ImDCRAt4cXeFMP4Z1xv9CzdMt3-2L5V4ZxSpt42xwJWJvHhYFrgr3UwETSUKXIaSoagNrswu4orrNAwrjZEpqeENu9DmR0YfRLo5TmPCAZr1OhIkn438z1zIW_ZwFCqc_qWoHyFTwwy5Qu5MYbAjUbBYS75B4ERWDUEgd7alkPrZKQijzRjp2IfXrMNZVjBbm_kKARSEwTE2DFU8c7AEqEwRCOI Oct 06 11:25:24 mcfvolumio volumio[900]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 06 11:25:24 mcfvolumio volumio[900]: info: New Spotify access token = BQDqTbO2ygarUmiuuZgcyR1mryT6ImDCRAt4cXeFMP4Z1xv9CzdMt3-2L5V4ZxSpt42xwJWJvHhYFrgr3UwETSUKXIaSoagNrswu4orrNAwrjZEpqeENu9DmR0YfRLo5TmPCAZr1OhIkn438z1zIW_ZwFCqc_qWoHyFTwwy5Qu5MYbAjUbBYS75B4ERWDUEgd7alkPrZKQijzRjp2IfXrMNZVjBbm_kKARSEwTE2DFU8c7AEqEwRCOI Oct 06 11:25:24 mcfvolumio volumio[900]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 06 11:25:24 mcfvolumio sudo[10436]: pam_unix(sudo:session): session closed for user root Oct 06 11:25:24 mcfvolumio volumio[900]: verbose: New Socket.io Connection to 192.168.0.107 from 192.168.0.215 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Engine version: 3 Transport: polling Total Clients: 7 Oct 06 11:25:24 mcfvolumio volumio[900]: SPOTIFY: User informations: {"display_name":"mcpfrid","external_urls":{"spotify":"https://open.spotify.com/user/mcpfrid"},"href":"https://api.spotify.com/v1/users/mcpfrid","id":"mcpfrid","images":[],"type":"user","uri":"spotify:user:mcpfrid","followers":{"href":null,"total":0},"country":"US","product":"premium","explicit_content":{"filter_enabled":false,"filter_locked":false},"email":"mcpfrid@gmail.com"} Oct 06 11:25:24 mcfvolumio volumio[900]: info: Creating Spotify config file Oct 06 11:25:24 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 11:25:24 mcfvolumio volumio[900]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 06 11:25:24 mcfvolumio volumio[900]: info: Spotify config file written Oct 06 11:25:24 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 06 11:25:24 mcfvolumio volumio[900]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Oct 06 11:25:24 mcfvolumio volumio[900]: info: CoreCommandRouter::volumioGetState Oct 06 11:25:24 mcfvolumio volumio[900]: info: CorePlayQueue::getTrack 0 Oct 06 11:25:24 mcfvolumio sudo[10439]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 06 11:25:24 mcfvolumio volumio[900]: info: CoreCommandRouter::volumioGetVisibleSources Oct 06 11:25:24 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 11:25:24 mcfvolumio sudo[10439]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 11:25:24 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 06 11:25:24 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 06 11:25:24 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 06 11:25:24 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 06 11:25:24 mcfvolumio systemd[1]: Stopping go-librespot Daemon... Oct 06 11:25:24 mcfvolumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 06 11:25:24 mcfvolumio systemd[1]: go-librespot-daemon.service: Succeeded. Oct 06 11:25:24 mcfvolumio systemd[1]: Stopped go-librespot Daemon. Oct 06 11:25:24 mcfvolumio volumio[900]: ------------------------------------ BT MESSAGE: BT STATUS: running Oct 06 11:25:24 mcfvolumio volumio[900]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Oct 06 11:25:24 mcfvolumio volumio[900]: info: Connection to go-librespot Websocket closed Oct 06 11:25:24 mcfvolumio systemd[1]: Started go-librespot Daemon. Oct 06 11:25:24 mcfvolumio sudo[10439]: pam_unix(sudo:session): session closed for user root Oct 06 11:25:24 mcfvolumio go-librespot[10441]: Librespot-go daemon starting... Oct 06 11:25:24 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:24-07:00" level=info msg="generated new device id: 0532e5401d06026847c2289583261b39012e3ef3" Oct 06 11:25:24 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:24-07:00" level=debug msg="stored credentials not found" Oct 06 11:25:24 mcfvolumio volumio[900]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 06 11:25:24 mcfvolumio volumio[900]: SPOTIFY: BQAsOdakwElQNZ-DM4b_jylwKAl7_u485T4u17KpXEHflu1IXUqK-WnkQBLFO5FZ771MnuQlwO8VL2T7zJxFsg__ASaHUTyculI7QZtU0bqW3QwaLlRcxtmFS4HouFncXoi-k9U2dKDrakb-yDhCmuU8gobd6lJQAEWFkn0zSGA-4DfIEwbFqeErnSFkbESB7GGAzai4Z-rY-D1caCnu9io9u2PwdQfiamtGcsSv2jIDXNb-uyWAwng Oct 06 11:25:24 mcfvolumio volumio[900]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 06 11:25:24 mcfvolumio volumio[900]: info: New Spotify access token = BQAsOdakwElQNZ-DM4b_jylwKAl7_u485T4u17KpXEHflu1IXUqK-WnkQBLFO5FZ771MnuQlwO8VL2T7zJxFsg__ASaHUTyculI7QZtU0bqW3QwaLlRcxtmFS4HouFncXoi-k9U2dKDrakb-yDhCmuU8gobd6lJQAEWFkn0zSGA-4DfIEwbFqeErnSFkbESB7GGAzai4Z-rY-D1caCnu9io9u2PwdQfiamtGcsSv2jIDXNb-uyWAwng Oct 06 11:25:24 mcfvolumio volumio[900]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 06 11:25:25 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:25-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 06 11:25:25 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:25-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 06 11:25:25 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:25-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 06 11:25:25 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:25-07:00" level=debug msg="zeroconf server listening on port 37585" Oct 06 11:25:25 mcfvolumio volumio[900]: SPOTIFY: User informations: {"display_name":"mcpfrid","external_urls":{"spotify":"https://open.spotify.com/user/mcpfrid"},"href":"https://api.spotify.com/v1/users/mcpfrid","id":"mcpfrid","images":[],"type":"user","uri":"spotify:user:mcpfrid","followers":{"href":null,"total":0},"country":"US","product":"premium","explicit_content":{"filter_enabled":false,"filter_locked":false},"email":"mcpfrid@gmail.com"} Oct 06 11:25:25 mcfvolumio volumio[900]: info: Spotify Successfully logged in Oct 06 11:25:25 mcfvolumio volumio[900]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 06 11:25:25 mcfvolumio volumio[900]: info: [1728239125123] CoreMusicLibrary::Adding element Spotify Oct 06 11:25:25 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 11:25:25 mcfvolumio volumio[900]: Cannot find translation for source TIDAL Oct 06 11:25:25 mcfvolumio volumio[900]: Cannot find translation for source Pandora Radio Oct 06 11:25:25 mcfvolumio volumio[900]: Cannot find translation for source Radio Paradise Oct 06 11:25:25 mcfvolumio volumio[900]: Cannot find translation for source Spotify Oct 06 11:25:25 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:25-07:00" level=debug msg="obtained new client token: AAAuQfe3sSgEBKpaKDYJKf33DYI97EdG2p95NDsPNIVu78yqvbguYLFPWbXw6j/FadcO/LIRNXDf2UfP8YrVYIhDxde3mzjgNnq5qyD1KjT6OZAEiBHhvbD/SEUBC23drEK0HUY4xjhxhe77xxFbfSq6r194YPi2cb+SwC6ufKCYv2cZWFJrr98SGPeKkxrLTh/5jcqP8RJLv48xKTji+x7vFdd3a+IHU3qyfdnpEQvL1Dzxg2lbZlsGNxms" Oct 06 11:25:25 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:25-07:00" level=info msg="connected to ap-guc3.spotify.com:4070" Oct 06 11:25:25 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:25-07:00" level=debug msg="completed keyexchange" Oct 06 11:25:25 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:25-07:00" level=debug msg="completed challenge" Oct 06 11:25:25 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:25-07:00" level=debug msg="authenticated as mcpfrid" Oct 06 11:25:26 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:26-07:00" level=debug msg="authenticated as mcpfrid" Oct 06 11:25:26 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:26-07:00" level=debug msg="dealer connection opened" Oct 06 11:25:26 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:26-07:00" level=debug msg="stored credentials for mcpfrid" Oct 06 11:25:26 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:26-07:00" level=debug msg="initializing zeroconf session, username: mcpfrid" Oct 06 11:25:26 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:26-07:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 06 11:25:26 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:26-07:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 06 11:25:26 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:26-07:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 06 11:25:26 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:26-07:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 06 11:25:26 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:26-07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 505" Oct 06 11:25:26 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:26-07:00" level=debug msg="autoplay enabled: false" Oct 06 11:25:26 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:26-07:00" level=debug msg="received connection id: MDI3N2UyZDktZGFjMS00YTZhLTkwMDItMGVkMjE2NjRiZmFmK2RlYWxlcit0Y3A6Ly8wYWNiZGE5MS5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArRDM1NTgxNjYxMDlCQjQ4QTlGMjA3MkI3MjZEOTg3NzhENTNENkQwNjVGNkQxOUEwNzgyQkE3NENCRDRCQkJGQQ==" Oct 06 11:25:26 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:26-07:00" level=debug msg="put connect state because NEW_DEVICE" Oct 06 11:25:27 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 06 11:25:27 mcfvolumio volumio[900]: info: Received Get System Info Oct 06 11:25:27 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 06 11:25:27 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 06 11:25:27 mcfvolumio volumio[900]: info: Discovery: Getting this device information Oct 06 11:25:27 mcfvolumio volumio[900]: info: CoreCommandRouter::volumioGetState Oct 06 11:25:27 mcfvolumio volumio[900]: info: CorePlayQueue::getTrack 0 Oct 06 11:25:27 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 06 11:25:27 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 06 11:25:27 mcfvolumio volumio[900]: info: Received Get System Info Oct 06 11:25:27 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 06 11:25:27 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 06 11:25:27 mcfvolumio volumio[900]: info: Discovery: Getting this device information Oct 06 11:25:27 mcfvolumio volumio[900]: info: CoreCommandRouter::volumioGetState Oct 06 11:25:27 mcfvolumio volumio[900]: info: CorePlayQueue::getTrack 0 Oct 06 11:25:27 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 06 11:25:27 mcfvolumio volumio[900]: info: Initializing connection to go-librespot Websocket Oct 06 11:25:27 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:27-07:00" level=debug msg="new websocket client" Oct 06 11:25:27 mcfvolumio volumio[900]: info: Connection to go-librespot Websocket established Oct 06 11:25:27 mcfvolumio volumio[900]: info: go-librespot daemon successfully initialized Oct 06 11:25:30 mcfvolumio volumio[900]: info: Getting Spotify volume Oct 06 11:25:30 mcfvolumio volumio[900]: info: Spotify volume: 100 Oct 06 11:25:30 mcfvolumio volumio[900]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Oct 06 11:25:30 mcfvolumio volumio[900]: info: Initializing connection to go-librespot Websocket Oct 06 11:25:30 mcfvolumio go-librespot[10441]: time="2024-10-06T11:25:30-07:00" level=debug msg="new websocket client" Oct 06 11:25:30 mcfvolumio volumio[900]: info: Connection to go-librespot Websocket established Oct 06 11:25:30 mcfvolumio volumio[900]: info: CoreCommandRouter::volumioGetState Oct 06 11:25:30 mcfvolumio volumio[900]: info: CorePlayQueue::getTrack 0 Oct 06 11:25:33 mcfvolumio volumio[900]: info: Getting Spotify volume Oct 06 11:25:33 mcfvolumio volumio[900]: info: Spotify volume: 100 Oct 06 11:25:33 mcfvolumio volumio[900]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Oct 06 11:25:33 mcfvolumio volumio[900]: info: CoreCommandRouter::volumioGetState Oct 06 11:25:33 mcfvolumio volumio[900]: info: CorePlayQueue::getTrack 0 Oct 06 11:25:43 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 06 11:25:43 mcfvolumio volumio[900]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 06 11:25:43 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 06 11:25:43 mcfvolumio volumio[900]: info: Received Get System Version Oct 06 11:25:43 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 06 11:25:43 mcfvolumio volumio[900]: info: Received Get System Info Oct 06 11:25:43 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 06 11:25:43 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 06 11:25:43 mcfvolumio volumio[900]: info: Discovery: Getting this device information Oct 06 11:25:43 mcfvolumio volumio[900]: info: CoreCommandRouter::volumioGetState Oct 06 11:25:43 mcfvolumio volumio[900]: info: CorePlayQueue::getTrack 0 Oct 06 11:25:43 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 06 11:25:45 mcfvolumio volumio[900]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Oct 06 11:25:45 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Oct 06 11:25:45 mcfvolumio volumio[900]: info: Creating Spotify config file Oct 06 11:25:45 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 11:25:45 mcfvolumio volumio[900]: info: Spotify config file written Oct 06 11:25:45 mcfvolumio sudo[10494]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 06 11:25:45 mcfvolumio sudo[10494]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 11:25:45 mcfvolumio systemd[1]: Stopping go-librespot Daemon... Oct 06 11:25:45 mcfvolumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 06 11:25:45 mcfvolumio systemd[1]: go-librespot-daemon.service: Succeeded. Oct 06 11:25:45 mcfvolumio systemd[1]: Stopped go-librespot Daemon. Oct 06 11:25:45 mcfvolumio volumio[900]: ------------------------------------ BT MESSAGE: BT STATUS: running Oct 06 11:25:45 mcfvolumio volumio[900]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Oct 06 11:25:45 mcfvolumio volumio[900]: info: Connection to go-librespot Websocket closed Oct 06 11:25:45 mcfvolumio volumio[900]: info: Connection to go-librespot Websocket closed Oct 06 11:25:45 mcfvolumio systemd[1]: Started go-librespot Daemon. Oct 06 11:25:45 mcfvolumio go-librespot[10497]: Librespot-go daemon starting... Oct 06 11:25:45 mcfvolumio sudo[10494]: pam_unix(sudo:session): session closed for user root Oct 06 11:25:45 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:45-07:00" level=info msg="generated new device id: e6b4f6c827dd4b72aff667ca40b4f3849ede0fff" Oct 06 11:25:45 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:45-07:00" level=debug msg="stored credentials found for mcpfrid" Oct 06 11:25:45 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:45-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Oct 06 11:25:45 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:45-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 06 11:25:45 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:45-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 06 11:25:45 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:45-07:00" level=debug msg="zeroconf server listening on port 34999" Oct 06 11:25:45 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:45-07:00" level=debug msg="obtained new client token: AACgQJF+zJzsWFo0MEdJThbCO9pyDmKOyIIhOY3M2+qzpcaacEoLSPAOUODRX8wgkjcgiJk3qzOrReGYMEzlvXkWJsYgBVugYHEeZz+ipAA2/7iA0TnJmEn+Xh99Ma12LAhVFC/DQcnB0XfSsanujJ6D0o7YPNjQeflUVHKK2ybX/WCDENHDemvpLquzB9xflz5TMaEmGvSyA3n3bVBLKwAamwUsoyiHXJ8VXWFskmLOEH8vMijI2IwL0tqRF84=" Oct 06 11:25:45 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:45-07:00" level=info msg="connected to ap-guc3.spotify.com:4070" Oct 06 11:25:45 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:45-07:00" level=debug msg="completed keyexchange" Oct 06 11:25:46 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:46-07:00" level=debug msg="completed challenge" Oct 06 11:25:46 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:46-07:00" level=debug msg="authenticated as mcpfrid" Oct 06 11:25:46 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:46-07:00" level=debug msg="authenticated as mcpfrid" Oct 06 11:25:46 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:46-07:00" level=debug msg="dealer connection opened" Oct 06 11:25:46 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:46-07:00" level=debug msg="initializing zeroconf session, username: mcpfrid" Oct 06 11:25:46 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:46-07:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 06 11:25:46 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:46-07:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 06 11:25:46 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:46-07:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 06 11:25:46 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:46-07:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 06 11:25:46 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:46-07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 505" Oct 06 11:25:46 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:46-07:00" level=debug msg="autoplay enabled: false" Oct 06 11:25:46 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:46-07:00" level=debug msg="received connection id: YWUwMmIwZGYtZGZiYS00ZmY4LWJjYjMtZjgzZGYwNWU5OGJkK2RlYWxlcit0Y3A6Ly8wYWNiZDk4Mi5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArRkYwNjg2NzA0NzdBNEYxNDdFMjA4RDVEREFGMzc1ODhFM0RFNTQxMjc1NDFFNEIwRkU3NDJFN0FFRjQyN0M3RQ==" Oct 06 11:25:46 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:46-07:00" level=debug msg="put connect state because NEW_DEVICE" Oct 06 11:25:48 mcfvolumio volumio[900]: info: Initializing connection to go-librespot Websocket Oct 06 11:25:48 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:48-07:00" level=debug msg="new websocket client" Oct 06 11:25:48 mcfvolumio volumio[900]: info: Connection to go-librespot Websocket established Oct 06 11:25:48 mcfvolumio volumio[900]: info: go-librespot daemon successfully initialized Oct 06 11:25:51 mcfvolumio volumio[900]: info: Getting Spotify volume Oct 06 11:25:51 mcfvolumio volumio[900]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Oct 06 11:25:51 mcfvolumio volumio[900]: info: Spotify volume: 100 Oct 06 11:25:51 mcfvolumio volumio[900]: info: CoreCommandRouter::volumioGetState Oct 06 11:25:51 mcfvolumio volumio[900]: info: CorePlayQueue::getTrack 0 Oct 06 11:25:51 mcfvolumio volumio[900]: info: Initializing connection to go-librespot Websocket Oct 06 11:25:51 mcfvolumio go-librespot[10497]: time="2024-10-06T11:25:51-07:00" level=debug msg="new websocket client" Oct 06 11:25:51 mcfvolumio volumio[900]: info: Connection to go-librespot Websocket established Oct 06 11:25:53 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 06 11:25:53 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 06 11:25:53 mcfvolumio volumio[900]: info: Discovery: Getting this device information Oct 06 11:25:53 mcfvolumio volumio[900]: info: CoreCommandRouter::volumioGetState Oct 06 11:25:53 mcfvolumio volumio[900]: info: CorePlayQueue::getTrack 0 Oct 06 11:25:53 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 06 11:25:54 mcfvolumio volumio[900]: info: Getting Spotify volume Oct 06 11:25:54 mcfvolumio volumio[900]: info: Spotify volume: 100 Oct 06 11:25:54 mcfvolumio volumio[900]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Oct 06 11:25:54 mcfvolumio volumio[900]: info: CoreCommandRouter::volumioGetState Oct 06 11:25:54 mcfvolumio volumio[900]: info: CorePlayQueue::getTrack 0 Oct 06 11:25:55 mcfvolumio volumio[900]: info: Listing playlists Oct 06 11:26:11 mcfvolumio volumio[900]: info: CoreCommandRouter::executeOnPlugin: multiroom , audioOutputPlay Oct 06 11:26:11 mcfvolumio volumio[900]: info: Error : CoreCommandRouter::executeOnPlugin: No method [audioOutputPlay] in plugin multiroom Oct 06 11:26:11 mcfvolumio volumio[900]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 06 11:26:11 mcfvolumio volumio[900]: TypeError: Cannot read property 'then' of undefined Oct 06 11:26:11 mcfvolumio volumio[900]: at outputs.audioOutputPlay (/volumio/app/plugins/audio_interface/outputs/index.js:367:9) Oct 06 11:26:11 mcfvolumio volumio[900]: at CoreCommandRouter.audioOutputPlay (/volumio/app/index.js:2260:30) Oct 06 11:26:11 mcfvolumio volumio[900]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1442:26) Oct 06 11:26:11 mcfvolumio volumio[900]: at Socket.emit (events.js:315:20) Oct 06 11:26:11 mcfvolumio volumio[900]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Oct 06 11:26:11 mcfvolumio volumio[900]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Oct 06 11:26:11 mcfvolumio volumio[900]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 06 11:26:11 mcfvolumio sudo[10516]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-06 11:25 Oct 06 11:26:11 mcfvolumio sudo[10516]: 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="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:01:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e0a6dc7e914e3fb93cbf2123f2f73eac"