-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Fri 2024-11-22 14:00:11 CET. -- Nov 22 13:59:07 minidsp-shd go-librespot[1023]: time="2024-11-22T13:59:07+01:00" level=debug msg="fetched chunk 15/19, size: 524288" uri="spotify:track:39DPuI340NQv3j3MQFHSO3" Nov 22 13:59:07 minidsp-shd volumio[661]: info: Received OAUTH Data Nov 22 13:59:07 minidsp-shd volumio[661]: info: Executing Spotify Oauth Login Nov 22 13:59:07 minidsp-shd volumio[661]: info: Saving Spotify Refresh Token Nov 22 13:59:07 minidsp-shd volumio[661]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 22 13:59:07 minidsp-shd volumio[661]: SPOTIFY: BQC5apkJkkSmXLcMUdO8xdrOpPYopGJIuCc3NvmfKvruouumoeB7Dr2fDJL_BvfHMCa3nyGrp6blxsqwNqTc-Z2M-HHTjA5uY-IqpZmkVj0PR998LZ4aABzmyaON-7hat6leujg_MH9O_pXQLVMjZBfnjQKrhzsksJzNFp_9l3lZM-OnGcJhlxFMARDkphmtE3508I01lWnyPbGn3HzQnPwUwrqZuUHNDCTjQX99b4fY37d8v2Td-t8SngY3LWkJ2cvyBo9jdcd11To Nov 22 13:59:07 minidsp-shd volumio[661]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 22 13:59:07 minidsp-shd volumio[661]: info: New Spotify access token = BQC5apkJkkSmXLcMUdO8xdrOpPYopGJIuCc3NvmfKvruouumoeB7Dr2fDJL_BvfHMCa3nyGrp6blxsqwNqTc-Z2M-HHTjA5uY-IqpZmkVj0PR998LZ4aABzmyaON-7hat6leujg_MH9O_pXQLVMjZBfnjQKrhzsksJzNFp_9l3lZM-OnGcJhlxFMARDkphmtE3508I01lWnyPbGn3HzQnPwUwrqZuUHNDCTjQX99b4fY37d8v2Td-t8SngY3LWkJ2cvyBo9jdcd11To Nov 22 13:59:07 minidsp-shd volumio[661]: info: Spotify credentials grant success - running version from March 24, 2019 Nov 22 13:59:08 minidsp-shd volumio[661]: SPOTIFY: User informations: {"country":"PL","display_name":"Bartosz.krawetkowski","email":"bartosz.krawetkowski@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/qs74dzp1qvun25auzmh848rvz"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/qs74dzp1qvun25auzmh848rvz","id":"qs74dzp1qvun25auzmh848rvz","images":[],"product":"premium","type":"user","uri":"spotify:user:qs74dzp1qvun25auzmh848rvz"} Nov 22 13:59:08 minidsp-shd volumio[661]: info: Creating Spotify config file Nov 22 13:59:08 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 22 13:59:08 minidsp-shd volumio[661]: info: Spotify config file written Nov 22 13:59:08 minidsp-shd sudo[2003]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 22 13:59:08 minidsp-shd sudo[2003]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 13:59:08 minidsp-shd systemd[1]: Stopping go-librespot Daemon... Nov 22 13:59:08 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Nov 22 13:59:08 minidsp-shd systemd[1]: go-librespot-daemon.service: Succeeded. Nov 22 13:59:08 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Nov 22 13:59:08 minidsp-shd volumio[661]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 22 13:59:08 minidsp-shd systemd[1]: Started go-librespot Daemon. Nov 22 13:59:08 minidsp-shd sudo[2003]: pam_unix(sudo:session): session closed for user root Nov 22 13:59:08 minidsp-shd go-librespot[2005]: Librespot-go daemon starting... Nov 22 13:59:08 minidsp-shd volumio[661]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Nov 22 13:59:08 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:08+01:00" level=info msg="generated new device id: f69e3e43b661df5ae0d042a0c17e963121fb09cd" Nov 22 13:59:08 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:08+01:00" level=debug msg="stored credentials found for qs74dzp1qvun25auzmh848rvz" Nov 22 13:59:08 minidsp-shd volumio[661]: info: Connection to go-librespot Websocket closed Nov 22 13:59:08 minidsp-shd volumio[661]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 22 13:59:08 minidsp-shd volumio[661]: SPOTIFY: BQCjF4wQJkyc_20cP_QTR7otmFQYw9SSHjgZmYFcVI2RoDEEwU61WwghSU38vrXU-tNim9TboFD75wPSi1V1olIzj1wtxMdoOr3pxS0a17NFARqOGwOxe9ioPHhPqqAmBwHkh6QmyGtHHwPBuz3FV3AISstiXXFt5GOzfU9SX4vl3gK2JinhhiGA5CauF9ALUYiofzb3DregzbWI0qpNMJXLTH-VSztT3Gt3iBTHLsRh-hjsenPu1bhSrfaby-Q8rwhmTRjrPCEditM Nov 22 13:59:08 minidsp-shd volumio[661]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 22 13:59:08 minidsp-shd volumio[661]: info: New Spotify access token = BQCjF4wQJkyc_20cP_QTR7otmFQYw9SSHjgZmYFcVI2RoDEEwU61WwghSU38vrXU-tNim9TboFD75wPSi1V1olIzj1wtxMdoOr3pxS0a17NFARqOGwOxe9ioPHhPqqAmBwHkh6QmyGtHHwPBuz3FV3AISstiXXFt5GOzfU9SX4vl3gK2JinhhiGA5CauF9ALUYiofzb3DregzbWI0qpNMJXLTH-VSztT3Gt3iBTHLsRh-hjsenPu1bhSrfaby-Q8rwhmTRjrPCEditM Nov 22 13:59:08 minidsp-shd volumio[661]: info: Spotify credentials grant success - running version from March 24, 2019 Nov 22 13:59:08 minidsp-shd sudo[2015]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 22 13:59:08 minidsp-shd sudo[2015]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 13:59:08 minidsp-shd sudo[2015]: pam_unix(sudo:session): session closed for user root Nov 22 13:59:08 minidsp-shd sudo[2018]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 22 13:59:08 minidsp-shd sudo[2018]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 13:59:08 minidsp-shd sudo[2018]: pam_unix(sudo:session): session closed for user root Nov 22 13:59:08 minidsp-shd volumio[661]: verbose: New Socket.io Connection to 192.168.3.3 from 192.168.3.2 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36 Total Clients: 7 Nov 22 13:59:08 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:08+01: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-gew1.spotify.com:80]" Nov 22 13:59:08 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:08+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Nov 22 13:59:08 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:08+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Nov 22 13:59:08 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:08+01:00" level=debug msg="zeroconf server listening on port 38971" Nov 22 13:59:08 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 22 13:59:08 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Nov 22 13:59:08 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetVisibleSources Nov 22 13:59:08 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 22 13:59:08 minidsp-shd volumio[661]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 22 13:59:08 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:08 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Nov 22 13:59:08 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Nov 22 13:59:08 minidsp-shd volumio[661]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Nov 22 13:59:08 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Nov 22 13:59:08 minidsp-shd volumio[661]: info: Received Get System Info Nov 22 13:59:08 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 22 13:59:08 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 22 13:59:08 minidsp-shd volumio[661]: info: Discovery: Getting this device information Nov 22 13:59:08 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:08 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 22 13:59:08 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:08 minidsp-shd volumio[661]: info: Listing playlists Nov 22 13:59:08 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Nov 22 13:59:08 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Nov 22 13:59:09 minidsp-shd volumio[661]: SPOTIFY: User informations: {"country":"PL","display_name":"Bartosz.krawetkowski","email":"bartosz.krawetkowski@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/qs74dzp1qvun25auzmh848rvz"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/qs74dzp1qvun25auzmh848rvz","id":"qs74dzp1qvun25auzmh848rvz","images":[],"product":"premium","type":"user","uri":"spotify:user:qs74dzp1qvun25auzmh848rvz"} Nov 22 13:59:09 minidsp-shd volumio[661]: info: Spotify Successfully logged in Nov 22 13:59:09 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 22 13:59:09 minidsp-shd volumio[661]: info: [1732280349041] CoreMusicLibrary::Adding element Spotify Nov 22 13:59:09 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 22 13:59:09 minidsp-shd volumio[661]: Cannot find translation for source Presets Nov 22 13:59:09 minidsp-shd volumio[661]: Cannot find translation for source TIDAL Nov 22 13:59:09 minidsp-shd volumio[661]: Cannot find translation for source Spotify Nov 22 13:59:09 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:09+01:00" level=debug msg="obtained new client token: AAAWrzXp8l6Msh5+ego1EVwb0QqHYctVD0PDMVF/naT052kSuVEBPSOlJW1uYZL6BJOEKA2rtfRSB8LC9jyvxXV8VaLySYkWIQ4MPtN9W0332ug5oxkBW/AA4XtElG9yMbfXkkoN+9QFoySZIi0x6jbVUYlLc+pfXxWVVqWHFtyRRoAH5n93YZFo3Mo0BSMKbAIFTvtMMHl7TVk7gNRf7Iv49k5Z/Dhe43oE9XF3jUcmtfd/pT1tCE1w/wY=" Nov 22 13:59:09 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Nov 22 13:59:09 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:09+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Nov 22 13:59:09 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:09+01:00" level=debug msg="completed keyexchange" Nov 22 13:59:09 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:09+01:00" level=debug msg="completed challenge" Nov 22 13:59:09 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:09+01:00" level=debug msg="authenticated as qs74dzp1qvun25auzmh848rvz" Nov 22 13:59:10 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:10+01:00" level=debug msg="authenticated as qs74dzp1qvun25auzmh848rvz" Nov 22 13:59:10 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:10+01:00" level=debug msg="dealer connection opened" Nov 22 13:59:10 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:10+01:00" level=debug msg="initializing zeroconf session, username: qs74dzp1qvun25auzmh848rvz" Nov 22 13:59:10 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:10+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Nov 22 13:59:10 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:10+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Nov 22 13:59:10 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:10+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Nov 22 13:59:10 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:10+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Nov 22 13:59:10 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:10+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Nov 22 13:59:10 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:10+01:00" level=debug msg="autoplay enabled: false" Nov 22 13:59:10 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:10+01:00" level=debug msg="received connection id: ZmZhNjAzMGYtMDVjYy00OWJlLTg4N2ItNTc0ZjMxMTZmMGJmK2RlYWxlcit0Y3A6Ly8wYWNhNTkyYy5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArRkI4MTczMDgxNzQxNEUyQTFDRTkxN0E2NzEyQzRERjBCNzc2NTM4NjA2REJBQ0I4MzcwQzA3MTkwQUY1NEE0Qw==" Nov 22 13:59:10 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 22 13:59:10 minidsp-shd volumio[661]: info: Received Get System Info Nov 22 13:59:10 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 22 13:59:10 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 22 13:59:10 minidsp-shd volumio[661]: info: Discovery: Getting this device information Nov 22 13:59:10 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:10 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 22 13:59:11 minidsp-shd volumio[661]: info: go-librespot daemon successfully initialized Nov 22 13:59:11 minidsp-shd volumio[661]: info: Initializing connection to go-librespot Websocket Nov 22 13:59:11 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:11+01:00" level=debug msg="new websocket client" Nov 22 13:59:11 minidsp-shd volumio[661]: info: Connection to go-librespot Websocket established Nov 22 13:59:11 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:11+01:00" level=debug msg="put connect state because NEW_DEVICE" Nov 22 13:59:11 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 22 13:59:11 minidsp-shd volumio[661]: info: Received Get System Info Nov 22 13:59:11 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 22 13:59:11 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 22 13:59:11 minidsp-shd volumio[661]: info: Discovery: Getting this device information Nov 22 13:59:11 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:11 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 22 13:59:14 minidsp-shd volumio[661]: info: Initializing connection to go-librespot Websocket Nov 22 13:59:14 minidsp-shd go-librespot[2005]: time="2024-11-22T13:59:14+01:00" level=debug msg="new websocket client" Nov 22 13:59:14 minidsp-shd volumio[661]: info: Connection to go-librespot Websocket established Nov 22 13:59:14 minidsp-shd volumio[661]: info: Getting Spotify volume Nov 22 13:59:14 minidsp-shd volumio[661]: info: Spotify volume: 100 Nov 22 13:59:14 minidsp-shd volumio[661]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Nov 22 13:59:14 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:14 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:14 minidsp-shd volumio[661]: SPOTIFY: SPOTIFY VOLUME 100 Nov 22 13:59:14 minidsp-shd volumio[661]: SPOTIFY: VOLUMIO VOLUME 94 Nov 22 13:59:14 minidsp-shd volumio[661]: SPOTIFY: DELTA VOLUME ENOUGH: true Nov 22 13:59:14 minidsp-shd volumio[661]: info: Setting Spotify Volume from Volumio: 94 Nov 22 13:59:15 minidsp-shd volumio[661]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Nov 22 13:59:15 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Nov 22 13:59:15 minidsp-shd volumio[661]: info: Creating Spotify config file Nov 22 13:59:15 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 22 13:59:15 minidsp-shd volumio[661]: info: Spotify config file written Nov 22 13:59:15 minidsp-shd sudo[2061]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 22 13:59:15 minidsp-shd sudo[2061]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 13:59:15 minidsp-shd systemd[1]: Stopping go-librespot Daemon... Nov 22 13:59:15 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Nov 22 13:59:15 minidsp-shd systemd[1]: go-librespot-daemon.service: Succeeded. Nov 22 13:59:15 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Nov 22 13:59:15 minidsp-shd volumio[661]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 22 13:59:15 minidsp-shd systemd[1]: Started go-librespot Daemon. Nov 22 13:59:15 minidsp-shd sudo[2061]: pam_unix(sudo:session): session closed for user root Nov 22 13:59:15 minidsp-shd go-librespot[2063]: Librespot-go daemon starting... Nov 22 13:59:15 minidsp-shd volumio[661]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Nov 22 13:59:15 minidsp-shd volumio[661]: info: Connection to go-librespot Websocket closed Nov 22 13:59:15 minidsp-shd volumio[661]: info: Connection to go-librespot Websocket closed Nov 22 13:59:15 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:15+01:00" level=info msg="generated new device id: d26f04ccbc312c9008c7966fb5a633219aab03bf" Nov 22 13:59:15 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:15+01:00" level=debug msg="stored credentials found for qs74dzp1qvun25auzmh848rvz" Nov 22 13:59:15 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:15+01: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-gew1.spotify.com:80]" Nov 22 13:59:15 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:15+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Nov 22 13:59:15 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:15+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Nov 22 13:59:15 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:15+01:00" level=debug msg="zeroconf server listening on port 42769" Nov 22 13:59:16 minidsp-shd volumio[661]: SPOTIFY: SETTING SPOTIFY VOLUME 94 Nov 22 13:59:16 minidsp-shd volumio[661]: info: Sending Spotify command with payload to local API: /player/volume Nov 22 13:59:16 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:16+01:00" level=debug msg="obtained new client token: AAAgj6HhDCeW2PPunkmQOsST8nXm3bOQyMBYBQVir2FqSOMAg3cjlPVkQ6PwFKAdJCxAZEK9BFszA+a4OzkZSch9BbUsNHn6G/axXmuQISeHnpsc1yCVPhc7PM8sJzv+xeTU/Rl/MqOvdAIvnMmC5TXrMUq6JtMO7M/B96r3IShRsrrs5D+wDGICqF8MXoUZwGj+N32WNQlvuzVXk5eC1202axpXh/xWJfpRTCPVuo7GxHRG6/+fT69xNZA=" Nov 22 13:59:16 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:16+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Nov 22 13:59:16 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:16+01:00" level=debug msg="completed keyexchange" Nov 22 13:59:16 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:16+01:00" level=debug msg="completed challenge" Nov 22 13:59:16 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:16+01:00" level=debug msg="authenticated as qs74dzp1qvun25auzmh848rvz" Nov 22 13:59:17 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:17+01:00" level=debug msg="authenticated as qs74dzp1qvun25auzmh848rvz" Nov 22 13:59:17 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:17+01:00" level=debug msg="dealer connection opened" Nov 22 13:59:17 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:17+01:00" level=debug msg="initializing zeroconf session, username: qs74dzp1qvun25auzmh848rvz" Nov 22 13:59:17 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:17+01:00" level=debug msg="update volume to 61602/65535" Nov 22 13:59:17 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:17+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Nov 22 13:59:17 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:17+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Nov 22 13:59:17 minidsp-shd volumio[661]: info: Getting Spotify volume Nov 22 13:59:17 minidsp-shd volumio[661]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Nov 22 13:59:17 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:17 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:17 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:17+01:00" level=error msg="failed put state after volume change" error="put state request failed with status 400: Require at least one of callback url or connection id" Nov 22 13:59:17 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:17+01:00" level=trace msg="emitting websocket event: volume" Nov 22 13:59:17 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:17+01:00" level=debug msg="received connection id: YTk2OTc3ZjYtYWMyNS00OTlkLWFlNzEtMGUwYzEwZGZhYmViK2RlYWxlcit0Y3A6Ly8wYWNhNThkYy5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArMEQ1RENEQzJEOTkxQjcyRDAwNjUyMkE5RkY3ODUyM0JENkQ4OUQ5Rjk3REUxREQ4NjFCM0RCRDUwMTY5NjVBQQ==" Nov 22 13:59:17 minidsp-shd volumio[661]: info: Spotify volume: 94 Nov 22 13:59:17 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:17+01:00" level=debug msg="put connect state because NEW_DEVICE" Nov 22 13:59:17 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:17+01:00" level=debug msg="update volume to 65535/65535" Nov 22 13:59:17 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:17+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 22 13:59:17 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:17+01:00" level=trace msg="emitting websocket event: volume" Nov 22 13:59:17 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:17+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Nov 22 13:59:17 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:17+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Nov 22 13:59:17 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:17+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Nov 22 13:59:17 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:17+01:00" level=debug msg="autoplay enabled: false" Nov 22 13:59:18 minidsp-shd volumio[661]: info: Initializing connection to go-librespot Websocket Nov 22 13:59:18 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:18+01:00" level=debug msg="new websocket client" Nov 22 13:59:18 minidsp-shd volumio[661]: info: Connection to go-librespot Websocket established Nov 22 13:59:18 minidsp-shd volumio[661]: info: go-librespot daemon successfully initialized Nov 22 13:59:20 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:21 minidsp-shd volumio[661]: info: Getting Spotify volume Nov 22 13:59:21 minidsp-shd volumio[661]: info: Initializing connection to go-librespot Websocket Nov 22 13:59:21 minidsp-shd volumio[661]: info: Spotify volume: 100 Nov 22 13:59:21 minidsp-shd go-librespot[2063]: time="2024-11-22T13:59:21+01:00" level=debug msg="new websocket client" Nov 22 13:59:21 minidsp-shd volumio[661]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Nov 22 13:59:21 minidsp-shd volumio[661]: info: Connection to go-librespot Websocket established Nov 22 13:59:21 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPause Nov 22 13:59:21 minidsp-shd volumio[661]: info: CoreStateMachine::pause Nov 22 13:59:21 minidsp-shd volumio[661]: info: CoreStateMachine::stPlaybackTimer Nov 22 13:59:21 minidsp-shd volumio[661]: info: CoreStateMachine::servicePause Nov 22 13:59:21 minidsp-shd volumio[661]: info: CoreCommandRouter::servicePause Nov 22 13:59:21 minidsp-shd volumio[661]: info: Spotify Received pause Nov 22 13:59:21 minidsp-shd volumio[661]: SPOTIFY: SPOTIFY PAUSE Nov 22 13:59:21 minidsp-shd volumio[661]: SPOTIFY: {"status":"play","title":"All I Want","artist":"Cassius","album":"15 Again (Deluxe Edition)","albumart":"https://i.scdn.co/image/ab67616d00001e0224ee286d8ebcaf83d4b899ab","uri":"spotify:track:39DPuI340NQv3j3MQFHSO3","trackType":"spotify","codec":"ogg","seek":146000,"duration":234,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":94,"dbVolume":-8,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"} Nov 22 13:59:21 minidsp-shd volumio[661]: info: Sending Spotify command to local API: /player/pause Nov 22 13:59:21 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:21 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:21 minidsp-shd volumio[661]: SPOTIFY: SPOTIFY VOLUME 100 Nov 22 13:59:21 minidsp-shd volumio[661]: SPOTIFY: VOLUMIO VOLUME 94 Nov 22 13:59:21 minidsp-shd volumio[661]: SPOTIFY: DELTA VOLUME ENOUGH: true Nov 22 13:59:21 minidsp-shd volumio[661]: info: Setting Spotify Volume from Volumio: 94 Nov 22 13:59:22 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioNext Nov 22 13:59:22 minidsp-shd volumio[661]: info: CoreStateMachine::next Nov 22 13:59:22 minidsp-shd volumio[661]: info: Spotify next Nov 22 13:59:22 minidsp-shd volumio[661]: info: Sending Spotify command to local API: /player/next Nov 22 13:59:22 minidsp-shd go-librespot[2063]: panic: runtime error: invalid memory address or nil pointer dereference Nov 22 13:59:22 minidsp-shd go-librespot[2063]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x14 pc=0x5731c0] Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 73 gp=0x18859e8 m=0 mp=0xaa6b38 [running]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: panic({0x5e79e8, 0xa5d0a0}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/panic.go:779 +0x12c fp=0x1b454d4 sp=0x1b45480 pc=0x579cc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.panicmem(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/panic.go:261 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.sigpanic() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/signal_unix.go:881 +0x39c fp=0x1b45504 sp=0x1b454d4 pc=0x739b8 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*AppPlayer).loadCurrentTrack(0x18a30e0, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/controls.go:190 +0x4c fp=0x1b4570c sp=0x1b45508 pc=0x5731c0 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*AppPlayer).advanceNext(0x18a30e0, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/controls.go:519 +0x44c fp=0x1b457fc sp=0x1b4570c pc=0x575fb4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*AppPlayer).skipNext(0x18a30e0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/controls.go:433 +0x24 fp=0x1b45838 sp=0x1b457fc pc=0x575a08 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*AppPlayer).handleApiRequest(0x18a30e0, {{0x662207, 0x4}, {0x0, 0x0}, 0x1b12200}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/player.go:347 +0x74 fp=0x1b458fc sp=0x1b45838 pc=0x57c468 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*AppPlayer).Run(0x18a30e0, 0x186b180) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/player.go:450 +0x530 fp=0x1b45fe0 sp=0x1b458fc pc=0x57d8ec Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*App).withAppPlayer.gowrap1() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:235 +0x30 fp=0x1b45fec sp=0x1b45fe0 pc=0x578ab4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1b45fec sp=0x1b45fec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by main.(*App).withAppPlayer in goroutine 1 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:235 +0x348 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 1 gp=0x1802128 m=nil [select]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c834, 0x0, 0x9, 0x3, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1c32d0c sp=0x1c32cf8 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.selectgo(0x1c32e0c, 0x199ddd8, 0x0, 0x0, 0x2, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/select.go:327 +0xaf0 fp=0x1c32dac sp=0x1c32d0c pc=0x6fc4c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: go-librespot/zeroconf.(*Zeroconf).Serve(0x1bc00a0, 0x1c32e88) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/zeroconf/zeroconf.go:268 +0x228 fp=0x1c32e50 sp=0x1c32dac pc=0x5282e8 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*App).withAppPlayer(0x18003f0, 0x19c60c0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:297 +0x4b0 fp=0x1c32ec0 sp=0x1c32e50 pc=0x578114 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*App).withCredentials(0x18003f0, {0x5f0038, 0x180e550}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:171 +0x3d4 fp=0x1c32f1c sp=0x1c32ec0 pc=0x5777ec Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*App).SpotifyToken(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:131 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.main() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:466 +0x530 fp=0x1c32fa8 sp=0x1c32f1c pc=0x579734 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.main() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:271 +0x2fc fp=0x1c32fec sp=0x1c32fa8 pc=0x5b904 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1c32fec sp=0x1c32fec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 2 gp=0x18027e8 m=nil [force gc (idle)]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c800, 0xaa54c0, 0x11, 0xa, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1842fd4 sp=0x1842fc0 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goparkunlock(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:408 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.forcegchelper() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:326 +0xe4 fp=0x1842fec sp=0x1842fd4 pc=0x5bcd0 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1842fec sp=0x1842fec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by runtime.init.5 in goroutine 1 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:314 +0x1c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 3 gp=0x1802b48 m=nil [GC sweep wait]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c800, 0xaa5a10, 0xc, 0x9, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x18437c4 sp=0x18437b0 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goparkunlock(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:408 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.bgsweep(0x186a000) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgcsweep.go:318 +0x11c fp=0x18437e4 sp=0x18437c4 pc=0x446d4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gcenable.gowrap1() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgc.go:203 +0x28 fp=0x18437ec sp=0x18437e4 pc=0x347f4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x18437ec sp=0x18437ec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by runtime.gcenable in goroutine 1 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgc.go:203 +0x74 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 4 gp=0x1802c68 m=nil [GC scavenge wait]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c800, 0xaa6020, 0xd, 0xa, 0x2) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1843fb4 sp=0x1843fa0 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goparkunlock(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:408 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.(*scavengerState).park(0xaa6020) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgcscavenge.go:425 +0x68 fp=0x1843fc8 sp=0x1843fb4 pc=0x419f4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.bgscavenge(0x186a000) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgcscavenge.go:658 +0x60 fp=0x1843fe4 sp=0x1843fc8 pc=0x4212c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gcenable.gowrap2() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgc.go:204 +0x28 fp=0x1843fec sp=0x1843fe4 pc=0x347a0 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1843fec sp=0x1843fec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by runtime.gcenable in goroutine 1 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgc.go:204 +0xbc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 5 gp=0x1803208 m=nil [finalizer wait]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c6ac, 0xad0b9c, 0x10, 0xa, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x184478c sp=0x1844778 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.runfinq() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mfinal.go:194 +0x110 fp=0x18447ec sp=0x184478c pc=0x335e0 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x18447ec sp=0x18447ec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by runtime.createfing in goroutine 1 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mfinal.go:164 +0x5c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 6 gp=0x18039e8 m=nil [IO wait]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c7f0, 0xf6f66f08, 0x2, 0x2, 0x5) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x18425dc sp=0x18425c8 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.netpollblock(0xf6f66ef8, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:573 +0x100 fp=0x18425f4 sp=0x18425dc pc=0x53758 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.runtime_pollWait(0xf6f66ef8, 0x72) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:345 +0x54 fp=0x1842608 sp=0x18425f4 pc=0x8e210 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).wait(0x1826fb8, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x184261c sp=0x1842608 pc=0x107770 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).waitRead(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:89 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*FD).Accept(0x1826fa0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_unix.go:611 +0x294 fp=0x1842664 sp=0x184261c pc=0x10bfdc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*netFD).accept(0x1826fa0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/fd_unix.go:172 +0x20 fp=0x18426cc sp=0x1842664 pc=0x2a1b6c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*TCPListener).accept(0x19103a8) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/tcpsock_posix.go:159 +0x20 fp=0x18426e4 sp=0x18426cc pc=0x2b9c6c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*TCPListener).Accept(0x19103a8) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/tcpsock.go:327 +0x30 fp=0x1842700 sp=0x18426e4 pc=0x2b8cd8 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*onceCloseListener).Accept(0x1a102a0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: :1 +0x34 fp=0x1842718 sp=0x1842700 pc=0x45df7c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*Server).Serve(0x1a0c0a8, {0x722144, 0x19103a8}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:3255 +0x314 fp=0x18427b0 sp=0x1842718 pc=0x43c638 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.Serve(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:2794 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*ApiServer).serve(0x1907a00) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:470 +0x5ec fp=0x18427e4 sp=0x18427b0 pc=0x56feb4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.NewApiServer.gowrap1() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:240 +0x28 fp=0x18427ec sp=0x18427e4 pc=0x56f588 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x18427ec sp=0x18427ec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by main.NewApiServer in goroutine 1 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:240 +0x224 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 37 gp=0x1803b08 m=nil [IO wait]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c7f0, 0xf6f66be8, 0x2, 0x2, 0x5) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1859ad4 sp=0x1859ac0 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.netpollblock(0xf6f66bd8, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:573 +0x100 fp=0x1859aec sp=0x1859ad4 pc=0x53758 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.runtime_pollWait(0xf6f66bd8, 0x72) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:345 +0x54 fp=0x1859b00 sp=0x1859aec pc=0x8e210 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).wait(0x18f2068, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x1859b14 sp=0x1859b00 pc=0x107770 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).waitRead(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:89 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*FD).Read(0x18f2050, {0x19da000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_unix.go:164 +0x238 fp=0x1859b5c sp=0x1859b14 pc=0x10895c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*netFD).Read(0x18f2050, {0x19da000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/fd_posix.go:55 +0x38 fp=0x1859b88 sp=0x1859b5c pc=0x29fc78 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*conn).Read(0x189a0e0, {0x19da000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/net.go:179 +0x48 fp=0x1859bb4 sp=0x1859b88 pc=0x2afe58 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*TCPConn).Read(0x189a0e0, {0x19da000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: :1 +0x44 fp=0x1859bd4 sp=0x1859bb4 pc=0x2c30ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*atLeastReader).Read(0x1a04240, {0x19da000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:806 +0x78 fp=0x1859c00 sp=0x1859bd4 pc=0x385680 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: bytes.(*Buffer).ReadFrom(0x18fe18c, {0x720960, 0x1a04240}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/bytes/buffer.go:211 +0xa4 fp=0x1859c3c sp=0x1859c00 pc=0x1363d4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).readFromUntil(0x18fe008, {0x71f4cc, 0x189a0e0}, 0x5) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:828 +0xd4 fp=0x1859c64 sp=0x1859c3c pc=0x3858dc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).readRecordOrCCS(0x18fe008, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:626 +0x134 fp=0x1859dc8 sp=0x1859c64 pc=0x382fdc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).readRecord(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:588 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).Read(0x18fe008, {0x1a25000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:1370 +0x15c fp=0x1859df8 sp=0x1859dc8 pc=0x388e4c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: bufio.(*Reader).Read(0x1812540, {0x1a28024, 0x9, 0x9}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/bufio/bufio.go:241 +0x214 fp=0x1859e1c sp=0x1859df8 pc=0x15a1ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: io.ReadAtLeast({0x71f6c0, 0x1812540}, {0x1a28024, 0x9, 0x9}, 0x9) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/io/io.go:335 +0x90 fp=0x1859e48 sp=0x1859e1c pc=0x101718 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: io.ReadFull(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/io/io.go:354 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.http2readFrameHeader({0x1a28024, 0x9, 0x9}, {0x71f6c0, 0x1812540}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:1638 +0x54 fp=0x1859e70 sp=0x1859e48 pc=0x3f2764 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*http2Framer).ReadFrame(0x1a28000) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:1902 +0x88 fp=0x1859eec sp=0x1859e70 pc=0x3f2efc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*http2clientConnReadLoop).run(0x1859fdc) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:9334 +0x150 fp=0x1859fa4 sp=0x1859eec pc=0x417718 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*http2ClientConn).readLoop(0x1a22008) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:9229 +0x68 fp=0x1859fe4 sp=0x1859fa4 pc=0x416c0c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*http2Transport).newClientConn.gowrap1() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:7879 +0x28 fp=0x1859fec sp=0x1859fe4 pc=0x40fc58 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1859fec sp=0x1859fec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by net/http.(*http2Transport).newClientConn in goroutine 36 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:7879 +0xcb0 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 21 gp=0x1803d48 m=nil [GC worker (idle)]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c6bc, 0x18a4ed0, 0x1a, 0xa, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1844f90 sp=0x1844f7c pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gcBgMarkWorker() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgc.go:1310 +0xec fp=0x1844fec sp=0x1844f90 pc=0x3741c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1844fec sp=0x1844fec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by runtime.gcBgMarkStartWorkers in goroutine 20 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgc.go:1234 +0x20 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 34 gp=0x1c16008 m=nil [GC worker (idle)]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c6bc, 0x1a26648, 0x1a, 0xa, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1c1c790 sp=0x1c1c77c pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gcBgMarkWorker() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgc.go:1310 +0xec fp=0x1c1c7ec sp=0x1c1c790 pc=0x3741c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1c1c7ec sp=0x1c1c7ec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by runtime.gcBgMarkStartWorkers in goroutine 20 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgc.go:1234 +0x20 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 22 gp=0x1884368 m=nil [GC worker (idle)]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c6bc, 0x18a4ee8, 0x1a, 0xa, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x183e790 sp=0x183e77c pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gcBgMarkWorker() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgc.go:1310 +0xec fp=0x183e7ec sp=0x183e790 pc=0x3741c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x183e7ec sp=0x183e7ec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by runtime.gcBgMarkStartWorkers in goroutine 20 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgc.go:1234 +0x20 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 35 gp=0x1c16128 m=nil [GC worker (idle)]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c6bc, 0x1a26660, 0x1a, 0xa, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1c1cf90 sp=0x1c1cf7c pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gcBgMarkWorker() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgc.go:1310 +0xec fp=0x1c1cfec sp=0x1c1cf90 pc=0x3741c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1c1cfec sp=0x1c1cfec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by runtime.gcBgMarkStartWorkers in goroutine 20 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgc.go:1234 +0x20 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 24 gp=0x1803328 m=nil [IO wait]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c7f0, 0xf6f66e68, 0x2, 0x2, 0x5) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1baead4 sp=0x1baeac0 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.netpollblock(0xf6f66e58, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:573 +0x100 fp=0x1baeaec sp=0x1baead4 pc=0x53758 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.runtime_pollWait(0xf6f66e58, 0x72) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:345 +0x54 fp=0x1baeb00 sp=0x1baeaec pc=0x8e210 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).wait(0x18a2068, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x1baeb14 sp=0x1baeb00 pc=0x107770 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).waitRead(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:89 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*FD).Read(0x18a2050, {0x18c0000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_unix.go:164 +0x238 fp=0x1baeb5c sp=0x1baeb14 pc=0x10895c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*netFD).Read(0x18a2050, {0x18c0000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/fd_posix.go:55 +0x38 fp=0x1baeb88 sp=0x1baeb5c pc=0x29fc78 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*conn).Read(0x189a028, {0x18c0000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/net.go:179 +0x48 fp=0x1baebb4 sp=0x1baeb88 pc=0x2afe58 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*TCPConn).Read(0x189a028, {0x18c0000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: :1 +0x44 fp=0x1baebd4 sp=0x1baebb4 pc=0x2c30ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*atLeastReader).Read(0x180f020, {0x18c0000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:806 +0x78 fp=0x1baec00 sp=0x1baebd4 pc=0x385680 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: bytes.(*Buffer).ReadFrom(0x18a818c, {0x720960, 0x180f020}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/bytes/buffer.go:211 +0xa4 fp=0x1baec3c sp=0x1baec00 pc=0x1363d4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).readFromUntil(0x18a8008, {0x71f4cc, 0x189a028}, 0x5) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:828 +0xd4 fp=0x1baec64 sp=0x1baec3c pc=0x3858dc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).readRecordOrCCS(0x18a8008, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:626 +0x134 fp=0x1baedc8 sp=0x1baec64 pc=0x382fdc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).readRecord(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:588 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).Read(0x18a8008, {0x1cdc000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:1370 +0x15c fp=0x1baedf8 sp=0x1baedc8 pc=0x388e4c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: bufio.(*Reader).Read(0x1894360, {0x1918624, 0x9, 0x9}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/bufio/bufio.go:241 +0x214 fp=0x1baee1c sp=0x1baedf8 pc=0x15a1ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: io.ReadAtLeast({0x71f6c0, 0x1894360}, {0x1918624, 0x9, 0x9}, 0x9) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/io/io.go:335 +0x90 fp=0x1baee48 sp=0x1baee1c pc=0x101718 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: io.ReadFull(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/io/io.go:354 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.http2readFrameHeader({0x1918624, 0x9, 0x9}, {0x71f6c0, 0x1894360}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:1638 +0x54 fp=0x1baee70 sp=0x1baee48 pc=0x3f2764 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*http2Framer).ReadFrame(0x1918600) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:1902 +0x88 fp=0x1baeeec sp=0x1baee70 pc=0x3f2efc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*http2clientConnReadLoop).run(0x1baefdc) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:9334 +0x150 fp=0x1baefa4 sp=0x1baeeec pc=0x417718 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*http2ClientConn).readLoop(0x1937208) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:9229 +0x68 fp=0x1baefe4 sp=0x1baefa4 pc=0x416c0c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*http2Transport).newClientConn.gowrap1() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:7879 +0x28 fp=0x1baefec sp=0x1baefe4 pc=0x40fc58 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd volumio[661]: info: Executing endpoint metavolumio Nov 22 13:59:22 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1baefec sp=0x1baefec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by net/http.(*http2Transport).newClientConn in goroutine 23 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:7879 +0xcb0 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 78 gp=0x18846c8 m=nil [select]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c834, 0x0, 0x9, 0x3, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x183f6a8 sp=0x183f694 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.selectgo(0x183f7a4, 0x183f76c, 0x0, 0x0, 0x5, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/select.go:327 +0xaf0 fp=0x183f748 sp=0x183f6a8 pc=0x6fc4c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.(*Conn).timeoutLoop(0x197e8c8) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/conn_notjs.go:153 +0x10c fp=0x183f7e4 sp=0x183f748 pc=0x4736f4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.newConn.gowrap1() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/conn_notjs.go:114 +0x28 fp=0x183f7ec sp=0x183f7e4 pc=0x4732e8 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x183f7ec sp=0x183f7ec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by nhooyr.io/websocket.newConn in goroutine 96 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/conn_notjs.go:114 +0x544 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 10 gp=0x1c165a8 m=nil [IO wait]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c7f0, 0xf6f66d28, 0x2, 0x2, 0x5) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1857e84 sp=0x1857e70 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.netpollblock(0xf6f66d18, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:573 +0x100 fp=0x1857e9c sp=0x1857e84 pc=0x53758 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.runtime_pollWait(0xf6f66d18, 0x72) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:345 +0x54 fp=0x1857eb0 sp=0x1857e9c pc=0x8e210 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).wait(0x18a3058, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x1857ec4 sp=0x1857eb0 pc=0x107770 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).waitRead(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:89 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*FD).RawRead(0x18a3040, 0x1b48090) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_unix.go:708 +0x164 fp=0x1857ef0 sp=0x1857ec4 pc=0x10cbe0 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*rawConn).Read(0x1a0b5d0, 0x1b48090) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/rawconn.go:44 +0x38 fp=0x1857f10 sp=0x1857ef0 pc=0x2b4094 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: golang.org/x/net/internal/socket.(*Conn).recvMsg(0x180f0c0, 0x1b48060, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/golang.org/x/net@v0.11.0/internal/socket/rawconn_msg.go:28 +0x154 fp=0x1857f40 sp=0x1857f10 pc=0x4c8e6c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: golang.org/x/net/internal/socket.(*Conn).RecvMsg(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/golang.org/x/net@v0.11.0/internal/socket/socket.go:247 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: golang.org/x/net/ipv4.(*payloadHandler).ReadFrom(0x1894458, {0x19b0000, 0x10000, 0x10000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/golang.org/x/net@v0.11.0/ipv4/payload_cmsg.go:32 +0x44c fp=0x1857f9c sp=0x1857f40 pc=0x4cce54 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: github.com/grandcat/zeroconf.(*Server).recv4(0x1890540, 0x1894450) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/github.com/grandcat/zeroconf@v1.0.0/server.go:254 +0xec fp=0x1857fe0 sp=0x1857f9c pc=0x5236e4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: github.com/grandcat/zeroconf.(*Server).mainloop.gowrap1() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/github.com/grandcat/zeroconf@v1.0.0/server.go:188 +0x30 fp=0x1857fec sp=0x1857fe0 pc=0x52339c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1857fec sp=0x1857fec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by github.com/grandcat/zeroconf.(*Server).mainloop in goroutine 26 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/github.com/grandcat/zeroconf@v1.0.0/server.go:188 +0x7c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 11 gp=0x1c166c8 m=nil [IO wait]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c7f0, 0xf6f66c88, 0x2, 0x2, 0x5) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1c1be5c sp=0x1c1be48 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.netpollblock(0xf6f66c78, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:573 +0x100 fp=0x1c1be74 sp=0x1c1be5c pc=0x53758 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.runtime_pollWait(0xf6f66c78, 0x72) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:345 +0x54 fp=0x1c1be88 sp=0x1c1be74 pc=0x8e210 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).wait(0x18a30a8, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd volumio[661]: info: Executing endpoint metavolumio Nov 22 13:59:22 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x1c1be9c sp=0x1c1be88 pc=0x107770 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).waitRead(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:89 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*FD).RawRead(0x18a3090, 0x1bb0090) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_unix.go:708 +0x164 fp=0x1c1bec8 sp=0x1c1be9c pc=0x10cbe0 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*rawConn).Read(0x1a0b5f0, 0x1bb0090) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/rawconn.go:44 +0x38 fp=0x1c1bee8 sp=0x1c1bec8 pc=0x2b4094 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: golang.org/x/net/internal/socket.(*Conn).recvMsg(0x180f0d0, 0x1bb0060, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/golang.org/x/net@v0.11.0/internal/socket/rawconn_msg.go:28 +0x154 fp=0x1c1bf18 sp=0x1c1bee8 pc=0x4c8e6c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: golang.org/x/net/internal/socket.(*Conn).RecvMsg(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/golang.org/x/net@v0.11.0/internal/socket/socket.go:247 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: golang.org/x/net/ipv6.(*payloadHandler).ReadFrom(0x1894488, {0x1bd2000, 0x10000, 0x10000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/golang.org/x/net@v0.11.0/ipv6/payload_cmsg.go:32 +0x2ec fp=0x1c1bf9c sp=0x1c1bf18 pc=0x4d07dc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: github.com/grandcat/zeroconf.(*Server).recv6(0x1890540, 0x1894480) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/github.com/grandcat/zeroconf@v1.0.0/server.go:282 +0xec fp=0x1c1bfe0 sp=0x1c1bf9c pc=0x5238d8 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: github.com/grandcat/zeroconf.(*Server).mainloop.gowrap2() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/github.com/grandcat/zeroconf@v1.0.0/server.go:191 +0x30 fp=0x1c1bfec sp=0x1c1bfe0 pc=0x523340 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1c1bfec sp=0x1c1bfec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by github.com/grandcat/zeroconf.(*Server).mainloop in goroutine 26 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/github.com/grandcat/zeroconf@v1.0.0/server.go:191 +0xe8 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 12 gp=0x1885208 m=nil [select]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c834, 0x0, 0x9, 0x3, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1840ea8 sp=0x1840e94 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.selectgo(0x1840fd4, 0x1840f6c, 0x0, 0x0, 0x2, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/select.go:327 +0xaf0 fp=0x1840f48 sp=0x1840ea8 pc=0x6fc4c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: go-librespot/ap.(*Accesspoint).pongAckTicker(0x1905ea8) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/ap/ap.go:319 +0x8c fp=0x1840fe4 sp=0x1840f48 pc=0x48cb7c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: go-librespot/ap.NewAccesspoint.gowrap1() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/ap/ap.go:67 +0x28 fp=0x1840fec sp=0x1840fe4 pc=0x48ad84 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1840fec sp=0x1840fec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by go-librespot/ap.NewAccesspoint in goroutine 1 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/ap/ap.go:67 +0x188 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 104 gp=0x1885328 m=nil [select]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c834, 0x0, 0x9, 0x3, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x19cf6a8 sp=0x19cf694 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.selectgo(0x19cf7a4, 0x19cf76c, 0x0, 0x0, 0x5, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/select.go:327 +0xaf0 fp=0x19cf748 sp=0x19cf6a8 pc=0x6fc4c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.(*Conn).timeoutLoop(0x1ba6648) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/conn_notjs.go:153 +0x10c fp=0x19cf7e4 sp=0x19cf748 pc=0x4736f4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.newConn.gowrap1() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/conn_notjs.go:114 +0x28 fp=0x19cf7ec sp=0x19cf7e4 pc=0x4732e8 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x19cf7ec sp=0x19cf7ec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by nhooyr.io/websocket.newConn in goroutine 94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/conn_notjs.go:114 +0x544 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 115 gp=0x1a4f0e8 m=nil [IO wait]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c7f0, 0xf6f66788, 0x2, 0x2, 0x5) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1c19eb4 sp=0x1c19ea0 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.netpollblock(0xf6f66778, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:573 +0x100 fp=0x1c19ecc sp=0x1c19eb4 pc=0x53758 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.runtime_pollWait(0xf6f66778, 0x72) Nov 22 13:59:22 minidsp-shd volumio[661]: info: Executing endpoint metavolumio Nov 22 13:59:22 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:345 +0x54 fp=0x1c19ee0 sp=0x1c19ecc pc=0x8e210 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).wait(0x1d421a8, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x1c19ef4 sp=0x1c19ee0 pc=0x107770 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).waitRead(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:89 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*FD).Read(0x1d42190, {0x1b1c44d, 0x1, 0x1}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_unix.go:164 +0x238 fp=0x1c19f3c sp=0x1c19ef4 pc=0x10895c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*netFD).Read(0x1d42190, {0x1b1c44d, 0x1, 0x1}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/fd_posix.go:55 +0x38 fp=0x1c19f68 sp=0x1c19f3c pc=0x29fc78 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*conn).Read(0x182e2d8, {0x1b1c44d, 0x1, 0x1}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/net.go:179 +0x48 fp=0x1c19f94 sp=0x1c19f68 pc=0x2afe58 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*TCPConn).Read(0x182e2d8, {0x1b1c44d, 0x1, 0x1}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: :1 +0x44 fp=0x1c19fb4 sp=0x1c19f94 pc=0x2c30ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*connReader).backgroundRead(0x1b1c440) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:681 +0x40 fp=0x1c19fe4 sp=0x1c19fb4 pc=0x431124 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*connReader).startBackgroundRead.gowrap2() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:677 +0x28 fp=0x1c19fec sp=0x1c19fe4 pc=0x43105c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1c19fec sp=0x1c19fec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by net/http.(*connReader).startBackgroundRead in goroutine 106 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:677 +0x160 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 89 gp=0x1a4f208 m=nil [IO wait]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c7f0, 0xf6f668c8, 0x2, 0x2, 0x5) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1bacad4 sp=0x1bacac0 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.netpollblock(0xf6f668b8, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:573 +0x100 fp=0x1bacaec sp=0x1bacad4 pc=0x53758 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.runtime_pollWait(0xf6f668b8, 0x72) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:345 +0x54 fp=0x1bacb00 sp=0x1bacaec pc=0x8e210 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).wait(0x1ca5dc8, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x1bacb14 sp=0x1bacb00 pc=0x107770 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).waitRead(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:89 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*FD).Read(0x1ca5db0, {0x19e5000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_unix.go:164 +0x238 fp=0x1bacb5c sp=0x1bacb14 pc=0x10895c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*netFD).Read(0x1ca5db0, {0x19e5000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/fd_posix.go:55 +0x38 fp=0x1bacb88 sp=0x1bacb5c pc=0x29fc78 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*conn).Read(0x189a2c0, {0x19e5000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/net.go:179 +0x48 fp=0x1bacbb4 sp=0x1bacb88 pc=0x2afe58 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*TCPConn).Read(0x189a2c0, {0x19e5000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: :1 +0x44 fp=0x1bacbd4 sp=0x1bacbb4 pc=0x2c30ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*atLeastReader).Read(0x1cb41d0, {0x19e5000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:806 +0x78 fp=0x1bacc00 sp=0x1bacbd4 pc=0x385680 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: bytes.(*Buffer).ReadFrom(0x18feccc, {0x720960, 0x1cb41d0}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/bytes/buffer.go:211 +0xa4 fp=0x1bacc3c sp=0x1bacc00 pc=0x1363d4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).readFromUntil(0x18feb48, {0x71f4cc, 0x189a2c0}, 0x5) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:828 +0xd4 fp=0x1bacc64 sp=0x1bacc3c pc=0x3858dc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).readRecordOrCCS(0x18feb48, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:626 +0x134 fp=0x1bacdc8 sp=0x1bacc64 pc=0x382fdc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).readRecord(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:588 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).Read(0x18feb48, {0x1b63000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:1370 +0x15c fp=0x1bacdf8 sp=0x1bacdc8 pc=0x388e4c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: bufio.(*Reader).Read(0x1b499e0, {0x1a00124, 0x9, 0x9}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/bufio/bufio.go:241 +0x214 fp=0x1bace1c sp=0x1bacdf8 pc=0x15a1ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: io.ReadAtLeast({0x71f6c0, 0x1b499e0}, {0x1a00124, 0x9, 0x9}, 0x9) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/io/io.go:335 +0x90 fp=0x1bace48 sp=0x1bace1c pc=0x101718 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: io.ReadFull(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/io/io.go:354 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.http2readFrameHeader({0x1a00124, 0x9, 0x9}, {0x71f6c0, 0x1b499e0}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:1638 +0x54 fp=0x1bace70 sp=0x1bace48 pc=0x3f2764 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*http2Framer).ReadFrame(0x1a00100) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:1902 +0x88 fp=0x1baceec sp=0x1bace70 pc=0x3f2efc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*http2clientConnReadLoop).run(0x1bacfdc) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:9334 +0x150 fp=0x1bacfa4 sp=0x1baceec pc=0x417718 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*http2ClientConn).readLoop(0x1bc4108) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:9229 +0x68 fp=0x1bacfe4 sp=0x1bacfa4 pc=0x416c0c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*http2Transport).newClientConn.gowrap1() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:7879 +0x28 fp=0x1bacfec sp=0x1bacfe4 pc=0x40fc58 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1bacfec sp=0x1bacfec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by net/http.(*http2Transport).newClientConn in goroutine 88 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:7879 +0xcb0 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 43 gp=0x1a4f328 m=nil [IO wait]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c7f0, 0xf6f66a08, 0x2, 0x2, 0x5) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1babad4 sp=0x1babac0 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.netpollblock(0xf6f669f8, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:573 +0x100 fp=0x1babaec sp=0x1babad4 pc=0x53758 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.runtime_pollWait(0xf6f669f8, 0x72) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:345 +0x54 fp=0x1babb00 sp=0x1babaec pc=0x8e210 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).wait(0x1b00568, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x1babb14 sp=0x1babb00 pc=0x107770 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).waitRead(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:89 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*FD).Read(0x1b00550, {0x1b14000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_unix.go:164 +0x238 fp=0x1babb5c sp=0x1babb14 pc=0x10895c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*netFD).Read(0x1b00550, {0x1b14000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/fd_posix.go:55 +0x38 fp=0x1babb88 sp=0x1babb5c pc=0x29fc78 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*conn).Read(0x1adcb00, {0x1b14000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/net.go:179 +0x48 fp=0x1babbb4 sp=0x1babb88 pc=0x2afe58 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*TCPConn).Read(0x1adcb00, {0x1b14000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: :1 +0x44 fp=0x1babbd4 sp=0x1babbb4 pc=0x2c30ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*atLeastReader).Read(0x1acd0e0, {0x1b14000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:806 +0x78 fp=0x1babc00 sp=0x1babbd4 pc=0x385680 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: bytes.(*Buffer).ReadFrom(0x18a938c, {0x720960, 0x1acd0e0}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/bytes/buffer.go:211 +0xa4 fp=0x1babc3c sp=0x1babc00 pc=0x1363d4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).readFromUntil(0x18a9208, {0x71f4cc, 0x1adcb00}, 0x5) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:828 +0xd4 fp=0x1babc64 sp=0x1babc3c pc=0x3858dc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).readRecordOrCCS(0x18a9208, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:626 +0x134 fp=0x1babdc8 sp=0x1babc64 pc=0x382fdc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).readRecord(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:588 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).Read(0x18a9208, {0x1a7d000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:1370 +0x15c fp=0x1babdf8 sp=0x1babdc8 pc=0x388e4c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: bufio.(*Reader).Read(0x1a76570, {0x1a282a4, 0x9, 0x9}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/bufio/bufio.go:241 +0x214 fp=0x1babe1c sp=0x1babdf8 pc=0x15a1ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: io.ReadAtLeast({0x71f6c0, 0x1a76570}, {0x1a282a4, 0x9, 0x9}, 0x9) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/io/io.go:335 +0x90 fp=0x1babe48 sp=0x1babe1c pc=0x101718 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: io.ReadFull(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/io/io.go:354 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.http2readFrameHeader({0x1a282a4, 0x9, 0x9}, {0x71f6c0, 0x1a76570}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:1638 +0x54 fp=0x1babe70 sp=0x1babe48 pc=0x3f2764 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*http2Framer).ReadFrame(0x1a28280) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:1902 +0x88 fp=0x1babeec sp=0x1babe70 pc=0x3f2efc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*http2clientConnReadLoop).run(0x1babfdc) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:9334 +0x150 fp=0x1babfa4 sp=0x1babeec pc=0x417718 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*http2ClientConn).readLoop(0x1a22108) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:9229 +0x68 fp=0x1babfe4 sp=0x1babfa4 pc=0x416c0c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*http2Transport).newClientConn.gowrap1() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:7879 +0x28 fp=0x1babfec sp=0x1babfe4 pc=0x40fc58 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1babfec sp=0x1babfec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by net/http.(*http2Transport).newClientConn in goroutine 42 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/h2_bundle.go:7879 +0xcb0 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 46 gp=0x1885448 m=nil [IO wait]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c7f0, 0xf6f66968, 0x2, 0x2, 0x5) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1baf938 sp=0x1baf924 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.netpollblock(0xf6f66958, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:573 +0x100 fp=0x1baf950 sp=0x1baf938 pc=0x53758 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.runtime_pollWait(0xf6f66958, 0x72) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:345 +0x54 fp=0x1baf964 sp=0x1baf950 pc=0x8e210 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).wait(0x1b00798, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x1baf978 sp=0x1baf964 pc=0x107770 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).waitRead(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:89 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*FD).Read(0x1b00780, {0x1b15000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_unix.go:164 +0x238 fp=0x1baf9c0 sp=0x1baf978 pc=0x10895c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*netFD).Read(0x1b00780, {0x1b15000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/fd_posix.go:55 +0x38 fp=0x1baf9ec sp=0x1baf9c0 pc=0x29fc78 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*conn).Read(0x1adcbe0, {0x1b15000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/net.go:179 +0x48 fp=0x1bafa18 sp=0x1baf9ec pc=0x2afe58 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*TCPConn).Read(0x1adcbe0, {0x1b15000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: :1 +0x44 fp=0x1bafa38 sp=0x1bafa18 pc=0x2c30ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*atLeastReader).Read(0x1cb4510, {0x1b15000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:806 +0x78 fp=0x1bafa64 sp=0x1bafa38 pc=0x385680 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: bytes.(*Buffer).ReadFrom(0x18a95cc, {0x720960, 0x1cb4510}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/bytes/buffer.go:211 +0xa4 fp=0x1bafaa0 sp=0x1bafa64 pc=0x1363d4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).readFromUntil(0x18a9448, {0x71f4cc, 0x1adcbe0}, 0x5) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:828 +0xd4 fp=0x1bafac8 sp=0x1bafaa0 pc=0x3858dc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).readRecordOrCCS(0x18a9448, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:626 +0x134 fp=0x1bafc2c sp=0x1bafac8 pc=0x382fdc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).readRecord(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:588 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: crypto/tls.(*Conn).Read(0x18a9448, {0x1c34000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/crypto/tls/conn.go:1370 +0x15c fp=0x1bafc5c sp=0x1bafc2c pc=0x388e4c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*readWriteCloserBody).Read(0x1b052f0, {0x1c34000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/transport.go:2429 +0xec fp=0x1bafc7c sp=0x1bafc5c pc=0x452f28 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: bufio.(*Reader).fill(0x1895740) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/bufio/bufio.go:110 +0x10c fp=0x1bafca0 sp=0x1bafc7c pc=0x159b20 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: bufio.(*Reader).ReadByte(0x1895740) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/bufio/bufio.go:269 +0x28 fp=0x1bafcac sp=0x1bafca0 pc=0x15a3a4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.readFrameHeader(0x1895740, {0x197e7b8, 0x8, 0x8}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/frame.go:54 +0x74 fp=0x1bafcec sp=0x1bafcac pc=0x476848 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.(*Conn).readFrameHeader(0x197e788, {0x722550, 0xad0b10}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:188 +0xb4 fp=0x1bafdac sp=0x1bafcec pc=0x4794ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.(*Conn).readLoop(0x197e788, {0x722550, 0xad0b10}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:146 +0x3c fp=0x1bafe70 sp=0x1bafdac pc=0x478f94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.(*Conn).reader(0x197e788, {0x722550, 0xad0b10}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:315 +0x108 fp=0x1bafefc sp=0x1bafe70 pc=0x47a1a8 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.(*Conn).Reader(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:30 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.(*Conn).Read(0x197e788, {0x722550, 0xad0b10}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:36 +0x30 fp=0x1baff24 sp=0x1bafefc pc=0x478878 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: go-librespot/dealer.(*Dealer).recvLoop(0x1c02148) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:153 +0x58 fp=0x1baffe4 sp=0x1baff24 pc=0x4b807c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: go-librespot/dealer.(*Dealer).ReceiveMessage.(*Dealer).startReceiving.func1.gowrap1() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:99 +0x28 fp=0x1baffec sp=0x1baffe4 pc=0x4b98d4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1baffec sp=0x1baffec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by go-librespot/dealer.(*Dealer).ReceiveMessage.(*Dealer).startReceiving.func1 in goroutine 73 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:99 +0x60 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 45 gp=0x1885568 m=nil [IO wait]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c7f0, 0xf6f66aa8, 0x2, 0x2, 0x5) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1858d70 sp=0x1858d5c pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.netpollblock(0xf6f66a98, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:573 +0x100 fp=0x1858d88 sp=0x1858d70 pc=0x53758 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.runtime_pollWait(0xf6f66a98, 0x72) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:345 +0x54 fp=0x1858d9c sp=0x1858d88 pc=0x8e210 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).wait(0x1cf7648, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x1858db0 sp=0x1858d9c pc=0x107770 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).waitRead(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:89 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*FD).Read(0x1cf7630, {0x1ad4484, 0x3, 0x3}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_unix.go:164 +0x238 fp=0x1858df8 sp=0x1858db0 pc=0x10895c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*netFD).Read(0x1cf7630, {0x1ad4484, 0x3, 0x3}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/fd_posix.go:55 +0x38 fp=0x1858e24 sp=0x1858df8 pc=0x29fc78 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*conn).Read(0x1adc1e0, {0x1ad4484, 0x3, 0x3}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/net.go:179 +0x48 fp=0x1858e50 sp=0x1858e24 pc=0x2afe58 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*TCPConn).Read(0x1adc1e0, {0x1ad4484, 0x3, 0x3}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: :1 +0x44 fp=0x1858e70 sp=0x1858e50 pc=0x2c30ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: io.ReadAtLeast({0x71f4cc, 0x1adc1e0}, {0x1ad4484, 0x3, 0x3}, 0x3) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/io/io.go:335 +0x90 fp=0x1858e9c sp=0x1858e70 pc=0x101718 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: io.ReadFull(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/io/io.go:354 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: go-librespot/ap.(*shannonConn).receivePacket(0x1812b10) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/ap/shannon.go:80 +0x130 fp=0x1858efc sp=0x1858e9c pc=0x48f544 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: go-librespot/ap.(*Accesspoint).recvLoop(0x1905ea8) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/ap/ap.go:251 +0x58 fp=0x1858fe4 sp=0x1858efc pc=0x48c40c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: go-librespot/ap.(*Accesspoint).Receive.(*Accesspoint).startReceiving.func1.gowrap1() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/ap/ap.go:240 +0x28 fp=0x1858fec sp=0x1858fe4 pc=0x48c388 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1858fec sp=0x1858fec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by go-librespot/ap.(*Accesspoint).Receive.(*Accesspoint).startReceiving.func1 in goroutine 73 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/ap/ap.go:240 +0x60 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 70 gp=0x1885688 m=nil [select]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c834, 0x0, 0x9, 0x3, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x19ce6a8 sp=0x19ce694 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.selectgo(0x19ce7a4, 0x19ce76c, 0x0, 0x0, 0x5, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/select.go:327 +0xaf0 fp=0x19ce748 sp=0x19ce6a8 pc=0x6fc4c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.(*Conn).timeoutLoop(0x197e788) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/conn_notjs.go:153 +0x10c fp=0x19ce7e4 sp=0x19ce748 pc=0x4736f4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.newConn.gowrap1() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/conn_notjs.go:114 +0x28 fp=0x19ce7ec sp=0x19ce7e4 pc=0x4732e8 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x19ce7ec sp=0x19ce7ec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by nhooyr.io/websocket.newConn in goroutine 1 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/conn_notjs.go:114 +0x544 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 71 gp=0x18857a8 m=nil [select]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c834, 0x0, 0x9, 0x3, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1841688 sp=0x1841674 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.selectgo(0x18417d4, 0x1841750, 0x0, 0x0, 0x2, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/select.go:327 +0xaf0 fp=0x1841728 sp=0x1841688 pc=0x6fc4c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: go-librespot/dealer.(*Dealer).pingTicker(0x1c02148) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:107 +0x8c fp=0x18417e4 sp=0x1841728 pc=0x4b7c38 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: go-librespot/dealer.NewDealer.gowrap1() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:57 +0x28 fp=0x18417ec sp=0x18417e4 pc=0x4b7708 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x18417ec sp=0x18417ec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by go-librespot/dealer.NewDealer in goroutine 1 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:57 +0x180 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 72 gp=0x18858c8 m=nil [select]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c834, 0x0, 0x9, 0x3, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1841e7c sp=0x1841e68 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.selectgo(0x1841fcc, 0x1841f44, 0x0, 0x0, 0x3, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/select.go:327 +0xaf0 fp=0x1841f1c sp=0x1841e7c pc=0x6fc4c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: go-librespot/player.(*Player).manageLoop(0x1891a80) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/player/player.go:109 +0x1e0 fp=0x1841fe4 sp=0x1841f1c pc=0x4a6974 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: go-librespot/player.NewPlayer.gowrap1() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/player/player.go:91 +0x28 fp=0x1841fec sp=0x1841fe4 pc=0x4a66a8 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1841fec sp=0x1841fec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by go-librespot/player.NewPlayer in goroutine 1 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/player/player.go:91 +0x1e4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 74 gp=0x1885b08 m=nil [chan receive]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c690, 0x186a2b0, 0xe, 0x7, 0x2) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x19ca748 sp=0x19ca734 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.chanrecv(0x186a280, 0x19ca7d0, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/chan.go:583 +0x4b0 fp=0x19ca784 sp=0x19ca748 pc=0x1f42c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.chanrecv2(0x186a280, 0x19ca7d0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/chan.go:447 +0x20 fp=0x19ca798 sp=0x19ca784 pc=0x1ef70 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*App).withAppPlayer.func1() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:245 +0x54 fp=0x19ca7ec sp=0x19ca798 pc=0x5789e4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x19ca7ec sp=0x19ca7ec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by main.(*App).withAppPlayer in goroutine 1 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:242 +0x3d4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 75 gp=0x1885d48 m=nil [chan receive]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c690, 0x186a230, 0xe, 0x7, 0x2) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x19caf3c sp=0x19caf28 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.chanrecv(0x186a200, 0x19cafe0, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/chan.go:583 +0x4b0 fp=0x19caf78 sp=0x19caf3c pc=0x1f42c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.chanrecv2(0x186a200, 0x19cafe0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/chan.go:447 +0x20 fp=0x19caf8c sp=0x19caf78 pc=0x1ef70 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*App).withAppPlayer.func2() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:261 +0x5c fp=0x19cafec sp=0x19caf8c pc=0x5785f8 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x19cafec sp=0x19cafec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by main.(*App).withAppPlayer in goroutine 1 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:258 +0x45c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 76 gp=0x1885e68 m=nil [IO wait]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c7f0, 0xf6f66dc8, 0x2, 0x2, 0x5) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x19cb5e8 sp=0x19cb5d4 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.netpollblock(0xf6f66db8, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:573 +0x100 fp=0x19cb600 sp=0x19cb5e8 pc=0x53758 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.runtime_pollWait(0xf6f66db8, 0x72) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:345 +0x54 fp=0x19cb614 sp=0x19cb600 pc=0x8e210 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).wait(0x18a3008, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x19cb628 sp=0x19cb614 pc=0x107770 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).waitRead(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:89 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*FD).Accept(0x18a2ff0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_unix.go:611 +0x294 fp=0x19cb670 sp=0x19cb628 pc=0x10bfdc Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*netFD).accept(0x18a2ff0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/fd_unix.go:172 +0x20 fp=0x19cb6d8 sp=0x19cb670 pc=0x2a1b6c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*TCPListener).accept(0x1cd3110) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/tcpsock_posix.go:159 +0x20 fp=0x19cb6f0 sp=0x19cb6d8 pc=0x2b9c6c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*TCPListener).Accept(0x1cd3110) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/tcpsock.go:327 +0x30 fp=0x19cb70c sp=0x19cb6f0 pc=0x2b8cd8 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*onceCloseListener).Accept(0x1a11e40) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: :1 +0x34 fp=0x19cb724 sp=0x19cb70c pc=0x45df7c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*Server).Serve(0x1c02328, {0x722144, 0x1cd3110}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:3255 +0x314 fp=0x19cb7bc sp=0x19cb724 pc=0x43c638 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.Serve(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:2794 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: go-librespot/zeroconf.(*Zeroconf).Serve.func2() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/zeroconf/zeroconf.go:265 +0x8c fp=0x19cb7ec sp=0x19cb7bc pc=0x5283e4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x19cb7ec sp=0x19cb7ec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by go-librespot/zeroconf.(*Zeroconf).Serve in goroutine 1 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/zeroconf/zeroconf.go:265 +0x160 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 94 gp=0x1b91208 m=nil [IO wait]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c7f0, 0xf6f66828, 0x2, 0x2, 0x5) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x18558a4 sp=0x1855890 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.netpollblock(0xf6f66818, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:573 +0x100 fp=0x18558bc sp=0x18558a4 pc=0x53758 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.runtime_pollWait(0xf6f66818, 0x72) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:345 +0x54 fp=0x18558d0 sp=0x18558bc pc=0x8e210 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).wait(0x1b007e8, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x18558e4 sp=0x18558d0 pc=0x107770 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).waitRead(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:89 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*FD).Read(0x1b007d0, {0x1b5c000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_unix.go:164 +0x238 fp=0x185592c sp=0x18558e4 pc=0x10895c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*netFD).Read(0x1b007d0, {0x1b5c000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/fd_posix.go:55 +0x38 fp=0x1855958 sp=0x185592c pc=0x29fc78 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*conn).Read(0x1adc268, {0x1b5c000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/net.go:179 +0x48 fp=0x1855984 sp=0x1855958 pc=0x2afe58 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*TCPConn).Read(0x1adc268, {0x1b5c000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: :1 +0x44 fp=0x18559a4 sp=0x1855984 pc=0x2c30ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: io.(*multiReader).Read(0x1cb42f0, {0x1b5c000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/io/multi.go:26 +0xb4 fp=0x18559d0 sp=0x18559a4 pc=0x102980 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: bufio.(*Reader).fill(0x1b49470) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/bufio/bufio.go:110 +0x10c fp=0x18559f4 sp=0x18559d0 pc=0x159b20 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: bufio.(*Reader).ReadByte(0x1b49470) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/bufio/bufio.go:269 +0x28 fp=0x1855a00 sp=0x18559f4 pc=0x15a3a4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.readFrameHeader(0x1b49470, {0x1ba6678, 0x8, 0x8}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/frame.go:54 +0x74 fp=0x1855a40 sp=0x1855a00 pc=0x476848 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.(*Conn).readFrameHeader(0x1ba6648, {0x722550, 0xad0b10}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:188 +0xb4 fp=0x1855b00 sp=0x1855a40 pc=0x4794ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.(*Conn).readLoop(0x1ba6648, {0x722550, 0xad0b10}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:146 +0x3c fp=0x1855bc4 sp=0x1855b00 pc=0x478f94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.(*Conn).reader(0x1ba6648, {0x722550, 0xad0b10}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:315 +0x108 fp=0x1855c50 sp=0x1855bc4 pc=0x47a1a8 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.(*Conn).Reader(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:30 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.(*Conn).Read(0x1ba6648, {0x722550, 0xad0b10}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:36 +0x30 fp=0x1855c78 sp=0x1855c50 pc=0x478878 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*ApiServer).serve.func14({0x722278, 0x1c020a8}, 0x1c02008) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:450 +0x22c fp=0x1855cd0 sp=0x1855c78 pc=0x5702f0 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.HandlerFunc.ServeHTTP(0x1a0a140, {0x722278, 0x1c020a8}, 0x1c02008) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:2166 +0x34 fp=0x1855ce0 sp=0x1855cd0 pc=0x438c1c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*ServeMux).ServeHTTP(0x1a00000, {0x722278, 0x1c020a8}, 0x1c02008) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:2683 +0x208 fp=0x1855d1c sp=0x1855ce0 pc=0x43aa7c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*ApiServer).serve.(*ApiServer).allowOriginMiddleware.func15({0x722278, 0x1c020a8}, 0x1c02008) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:273 +0xa4 fp=0x1855d40 sp=0x1855d1c pc=0x5700ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.HandlerFunc.ServeHTTP(0x1a04120, {0x722278, 0x1c020a8}, 0x1c02008) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:2166 +0x34 fp=0x1855d50 sp=0x1855d40 pc=0x438c1c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.serverHandler.ServeHTTP({0x1a0c0a8}, {0x722278, 0x1c020a8}, 0x1c02008) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:3137 +0xe0 fp=0x1855d6c sp=0x1855d50 pc=0x43c20c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*conn).serve(0x1bea120, {0x722570, 0x1a12138}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:2039 +0x61c fp=0x1855fdc sp=0x1855d6c pc=0x43745c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*Server).Serve.gowrap3() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:3285 +0x38 fp=0x1855fec sp=0x1855fdc pc=0x43cab0 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1855fec sp=0x1855fec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by net/http.(*Server).Serve in goroutine 6 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:3285 +0x468 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 96 gp=0x1c16d88 m=nil [IO wait]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c7f0, 0xf6f66b48, 0x2, 0x2, 0x5) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x18528a4 sp=0x1852890 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.netpollblock(0xf6f66b38, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:573 +0x100 fp=0x18528bc sp=0x18528a4 pc=0x53758 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.runtime_pollWait(0xf6f66b38, 0x72) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:345 +0x54 fp=0x18528d0 sp=0x18528bc pc=0x8e210 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).wait(0x1b00ab8, 0x72, 0x0) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x18528e4 sp=0x18528d0 pc=0x107770 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*pollDesc).waitRead(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:89 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: internal/poll.(*FD).Read(0x1b00aa0, {0x1c44000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_unix.go:164 +0x238 fp=0x185292c sp=0x18528e4 pc=0x10895c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*netFD).Read(0x1b00aa0, {0x1c44000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/fd_posix.go:55 +0x38 fp=0x1852958 sp=0x185292c pc=0x29fc78 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*conn).Read(0x1adc290, {0x1c44000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/net.go:179 +0x48 fp=0x1852984 sp=0x1852958 pc=0x2afe58 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net.(*TCPConn).Read(0x1adc290, {0x1c44000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: :1 +0x44 fp=0x18529a4 sp=0x1852984 pc=0x2c30ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: io.(*multiReader).Read(0x1896200, {0x1c44000, 0x1000, 0x1000}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/io/multi.go:26 +0xb4 fp=0x18529d0 sp=0x18529a4 pc=0x102980 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: bufio.(*Reader).fill(0x1c92060) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/bufio/bufio.go:110 +0x10c fp=0x18529f4 sp=0x18529d0 pc=0x159b20 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: bufio.(*Reader).ReadByte(0x1c92060) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/bufio/bufio.go:269 +0x28 fp=0x1852a00 sp=0x18529f4 pc=0x15a3a4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.readFrameHeader(0x1c92060, {0x197e8f8, 0x8, 0x8}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/frame.go:54 +0x74 fp=0x1852a40 sp=0x1852a00 pc=0x476848 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.(*Conn).readFrameHeader(0x197e8c8, {0x722550, 0xad0b10}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:188 +0xb4 fp=0x1852b00 sp=0x1852a40 pc=0x4794ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.(*Conn).readLoop(0x197e8c8, {0x722550, 0xad0b10}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:146 +0x3c fp=0x1852bc4 sp=0x1852b00 pc=0x478f94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.(*Conn).reader(0x197e8c8, {0x722550, 0xad0b10}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:315 +0x108 fp=0x1852c50 sp=0x1852bc4 pc=0x47a1a8 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.(*Conn).Reader(...) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:30 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: nhooyr.io/websocket.(*Conn).Read(0x197e8c8, {0x722550, 0xad0b10}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:36 +0x30 fp=0x1852c78 sp=0x1852c50 pc=0x478878 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*ApiServer).serve.func14({0x722278, 0x1a0ce68}, 0x1a0cdc8) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:450 +0x22c fp=0x1852cd0 sp=0x1852c78 pc=0x5702f0 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.HandlerFunc.ServeHTTP(0x1a0a140, {0x722278, 0x1a0ce68}, 0x1a0cdc8) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:2166 +0x34 fp=0x1852ce0 sp=0x1852cd0 pc=0x438c1c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*ServeMux).ServeHTTP(0x1a00000, {0x722278, 0x1a0ce68}, 0x1a0cdc8) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:2683 +0x208 fp=0x1852d1c sp=0x1852ce0 pc=0x43aa7c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*ApiServer).serve.(*ApiServer).allowOriginMiddleware.func15({0x722278, 0x1a0ce68}, 0x1a0cdc8) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:273 +0xa4 fp=0x1852d40 sp=0x1852d1c pc=0x5700ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.HandlerFunc.ServeHTTP(0x1a04120, {0x722278, 0x1a0ce68}, 0x1a0cdc8) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:2166 +0x34 fp=0x1852d50 sp=0x1852d40 pc=0x438c1c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.serverHandler.ServeHTTP({0x1a0c0a8}, {0x722278, 0x1a0ce68}, 0x1a0cdc8) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:3137 +0xe0 fp=0x1852d6c sp=0x1852d50 pc=0x43c20c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*conn).serve(0x1bea180, {0x722570, 0x1a12138}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:2039 +0x61c fp=0x1852fdc sp=0x1852d6c pc=0x43745c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*Server).Serve.gowrap3() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:3285 +0x38 fp=0x1852fec sp=0x1852fdc pc=0x43cab0 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1852fec sp=0x1852fec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by net/http.(*Server).Serve in goroutine 6 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:3285 +0x468 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: goroutine 106 gp=0x1c16ea8 m=nil [chan receive]: Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.gopark(0x68c690, 0x1b12230, 0xe, 0x7, 0x2) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1c33bdc sp=0x1c33bc8 pc=0x5be94 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.chanrecv(0x1b12200, 0x1c33c9c, 0x1) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/chan.go:583 +0x4b0 fp=0x1c33c18 sp=0x1c33bdc pc=0x1f42c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.chanrecv1(0x1b12200, 0x1c33c9c) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/chan.go:442 +0x20 fp=0x1c33c2c sp=0x1c33c18 pc=0x1ef4c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*ApiServer).handleRequest(0x1907a00, {{0x662207, 0x4}, {0x0, 0x0}, 0x1b12200}, {0x722278, 0x1bf5048}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:253 +0x70 fp=0x1c33cac sp=0x1c33c2c pc=0x56f624 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*ApiServer).serve.func6({0x722278, 0x1bf5048}, 0x1bf4fa8) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:327 +0x9c fp=0x1c33cd0 sp=0x1c33cac pc=0x571228 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.HandlerFunc.ServeHTTP(0x1a0a080, {0x722278, 0x1bf5048}, 0x1bf4fa8) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:2166 +0x34 fp=0x1c33ce0 sp=0x1c33cd0 pc=0x438c1c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*ServeMux).ServeHTTP(0x1a00000, {0x722278, 0x1bf5048}, 0x1bf4fa8) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:2683 +0x208 fp=0x1c33d1c sp=0x1c33ce0 pc=0x43aa7c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: main.(*ApiServer).serve.(*ApiServer).allowOriginMiddleware.func15({0x722278, 0x1bf5048}, 0x1bf4fa8) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:273 +0xa4 fp=0x1c33d40 sp=0x1c33d1c pc=0x5700ac Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.HandlerFunc.ServeHTTP(0x1a04120, {0x722278, 0x1bf5048}, 0x1bf4fa8) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:2166 +0x34 fp=0x1c33d50 sp=0x1c33d40 pc=0x438c1c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.serverHandler.ServeHTTP({0x1a0c0a8}, {0x722278, 0x1bf5048}, 0x1bf4fa8) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:3137 +0xe0 fp=0x1c33d6c sp=0x1c33d50 pc=0x43c20c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*conn).serve(0x1cb8300, {0x722570, 0x1a12138}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:2039 +0x61c fp=0x1c33fdc sp=0x1c33d6c pc=0x43745c Nov 22 13:59:22 minidsp-shd go-librespot[2063]: net/http.(*Server).Serve.gowrap3() Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:3285 +0x38 fp=0x1c33fec sp=0x1c33fdc pc=0x43cab0 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: runtime.goexit({}) Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1c33fec sp=0x1c33fec pc=0x92ad4 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: created by net/http.(*Server).Serve in goroutine 6 Nov 22 13:59:22 minidsp-shd go-librespot[2063]: /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:3285 +0x468 Nov 22 13:59:22 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Nov 22 13:59:22 minidsp-shd volumio[661]: error: Failed to send command to Spotify local API: /player/next: Error: socket hang up Nov 22 13:59:22 minidsp-shd go-librespot[2063]: Aborted Nov 22 13:59:22 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 22 13:59:22 minidsp-shd volumio[661]: info: Connection to go-librespot Websocket closed Nov 22 13:59:22 minidsp-shd volumio[661]: info: Connection to go-librespot Websocket closed Nov 22 13:59:23 minidsp-shd volumio[661]: SPOTIFY: SETTING SPOTIFY VOLUME 94 Nov 22 13:59:23 minidsp-shd volumio[661]: info: Sending Spotify command with payload to local API: /player/volume Nov 22 13:59:23 minidsp-shd volumio[661]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 22 13:59:24 minidsp-shd volumio[661]: info: Getting Spotify volume Nov 22 13:59:24 minidsp-shd volumio[661]: (node:661) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 22 13:59:24 minidsp-shd volumio[661]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Nov 22 13:59:24 minidsp-shd volumio[661]: (node:661) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1) Nov 22 13:59:24 minidsp-shd volumio[661]: (node:661) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code. Nov 22 13:59:24 minidsp-shd volumio[661]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Nov 22 13:59:24 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:24 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:25 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPrevious Nov 22 13:59:25 minidsp-shd volumio[661]: info: Spotify previous Nov 22 13:59:25 minidsp-shd volumio[661]: info: Sending Spotify command to local API: /player/prev Nov 22 13:59:25 minidsp-shd volumio[661]: error: Failed to send command to Spotify local API: /player/prev: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 22 13:59:25 minidsp-shd volumio[661]: info: Initializing connection to go-librespot Websocket Nov 22 13:59:25 minidsp-shd volumio[661]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 22 13:59:25 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 22 13:59:25 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Nov 22 13:59:25 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Nov 22 13:59:25 minidsp-shd systemd[1]: Started go-librespot Daemon. Nov 22 13:59:25 minidsp-shd go-librespot[2074]: Librespot-go daemon starting... Nov 22 13:59:25 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:25+01:00" level=info msg="generated new device id: 46c21bd5a919c72f5f424cc4b377950fc8d2ca61" Nov 22 13:59:25 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:25+01:00" level=debug msg="stored credentials found for qs74dzp1qvun25auzmh848rvz" Nov 22 13:59:26 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:26+01: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-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 22 13:59:26 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:26+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 22 13:59:26 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:26+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 22 13:59:26 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:26+01:00" level=debug msg="zeroconf server listening on port 37745" Nov 22 13:59:26 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPause Nov 22 13:59:26 minidsp-shd volumio[661]: info: CoreStateMachine::pause Nov 22 13:59:26 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:26+01:00" level=debug msg="obtained new client token: AACWQsb0NvGQL+Xv09N/pqRHGqR4LBkL3k4pD95zpkuUWnq2IARih4q7amg9dVG6fcgBZOKphFj0HzsKPzLYqJhyaYmaBdFWbpeLGnHmByX+i/8vVhrRi8LXCy5sHWJzGG2057yflnST870K5/uHV+iHkIBGXWxeKMazHk/e7cX7Way8+6UgKXgRDHvidQEWC658p9hRnfvcDmYPuxs3Boz3kz8eEhVv8PtnmmBwfINGFd3xzdDgnIBrPVet0Q==" Nov 22 13:59:26 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:26+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Nov 22 13:59:26 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:26+01:00" level=debug msg="completed keyexchange" Nov 22 13:59:27 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Nov 22 13:59:27 minidsp-shd volumio[661]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Nov 22 13:59:27 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Nov 22 13:59:27 minidsp-shd volumio[661]: info: Received Get System Version Nov 22 13:59:27 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 22 13:59:27 minidsp-shd volumio[661]: info: Received Get System Info Nov 22 13:59:27 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 22 13:59:27 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 22 13:59:27 minidsp-shd volumio[661]: info: Discovery: Getting this device information Nov 22 13:59:27 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:27 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 22 13:59:27 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:27+01:00" level=debug msg="completed challenge" Nov 22 13:59:27 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:27+01:00" level=debug msg="authenticated as qs74dzp1qvun25auzmh848rvz" Nov 22 13:59:27 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:27+01:00" level=debug msg="authenticated as qs74dzp1qvun25auzmh848rvz" Nov 22 13:59:27 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:27+01:00" level=debug msg="dealer connection opened" Nov 22 13:59:27 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:27+01:00" level=debug msg="initializing zeroconf session, username: qs74dzp1qvun25auzmh848rvz" Nov 22 13:59:27 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:27+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Nov 22 13:59:27 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:27+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Nov 22 13:59:27 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:27+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Nov 22 13:59:27 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:27+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Nov 22 13:59:27 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:27+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Nov 22 13:59:27 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:27+01:00" level=debug msg="autoplay enabled: false" Nov 22 13:59:27 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:27+01:00" level=debug msg="received connection id: ZDNiZWQ3YjQtNzQzNC00ZTdmLWE4NmUtZmY0MGI0NTFiYzIwK2RlYWxlcit0Y3A6Ly8wYWNhNTkwMS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArREExRTU2NEJFRjFDMzcwNTdFMDg0NTFBMjA1RDRCMTY5NjdBNjhGMkQ5NjYxODUyRTBFMkRFOThEOEQwRDk3OQ==" Nov 22 13:59:28 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:28+01:00" level=debug msg="put connect state because NEW_DEVICE" Nov 22 13:59:28 minidsp-shd volumio[661]: info: Initializing connection to go-librespot Websocket Nov 22 13:59:28 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:28+01:00" level=debug msg="new websocket client" Nov 22 13:59:28 minidsp-shd volumio[661]: info: Connection to go-librespot Websocket established Nov 22 13:59:30 minidsp-shd sudo[2084]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 22 13:59:30 minidsp-shd sudo[2084]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 13:59:30 minidsp-shd sudo[2084]: pam_unix(sudo:session): session closed for user root Nov 22 13:59:30 minidsp-shd sudo[2087]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 22 13:59:30 minidsp-shd sudo[2087]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 13:59:30 minidsp-shd sudo[2087]: pam_unix(sudo:session): session closed for user root Nov 22 13:59:30 minidsp-shd volumio[661]: verbose: New Socket.io Connection to 192.168.3.3 from 192.168.3.2 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36 Total Clients: 8 Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Nov 22 13:59:30 minidsp-shd volumio[661]: info: Received Get System Info Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 22 13:59:30 minidsp-shd volumio[661]: info: Discovery: Getting this device information Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetVisibleSources Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Nov 22 13:59:30 minidsp-shd volumio[661]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Nov 22 13:59:30 minidsp-shd volumio[661]: info: Received Get System Info Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 22 13:59:30 minidsp-shd volumio[661]: info: Discovery: Getting this device information Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:30 minidsp-shd volumio[661]: info: Listing playlists Nov 22 13:59:30 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Nov 22 13:59:31 minidsp-shd volumio[661]: info: Getting Spotify volume Nov 22 13:59:31 minidsp-shd volumio[661]: info: Spotify volume: 100 Nov 22 13:59:31 minidsp-shd volumio[661]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Nov 22 13:59:31 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:31 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:31 minidsp-shd volumio[661]: SPOTIFY: SPOTIFY VOLUME 100 Nov 22 13:59:31 minidsp-shd volumio[661]: SPOTIFY: VOLUMIO VOLUME 94 Nov 22 13:59:31 minidsp-shd volumio[661]: SPOTIFY: DELTA VOLUME ENOUGH: true Nov 22 13:59:31 minidsp-shd volumio[661]: info: Setting Spotify Volume from Volumio: 94 Nov 22 13:59:32 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 22 13:59:32 minidsp-shd volumio[661]: info: Received Get System Info Nov 22 13:59:32 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 22 13:59:32 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 22 13:59:32 minidsp-shd volumio[661]: info: Discovery: Getting this device information Nov 22 13:59:32 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:32 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 22 13:59:33 minidsp-shd sudo[2092]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 22 13:59:33 minidsp-shd sudo[2092]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 13:59:33 minidsp-shd sudo[2092]: pam_unix(sudo:session): session closed for user root Nov 22 13:59:33 minidsp-shd sudo[2095]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 22 13:59:33 minidsp-shd sudo[2095]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 13:59:33 minidsp-shd sudo[2095]: pam_unix(sudo:session): session closed for user root Nov 22 13:59:33 minidsp-shd volumio[661]: verbose: New Socket.io Connection to 192.168.3.3 from 192.168.3.2 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36 Total Clients: 8 Nov 22 13:59:33 minidsp-shd volumio[661]: SPOTIFY: SETTING SPOTIFY VOLUME 94 Nov 22 13:59:33 minidsp-shd volumio[661]: info: Sending Spotify command with payload to local API: /player/volume Nov 22 13:59:33 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:33+01:00" level=debug msg="update volume to 61602/65535" Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Nov 22 13:59:33 minidsp-shd volumio[661]: info: Received Get System Info Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 22 13:59:33 minidsp-shd volumio[661]: info: Discovery: Getting this device information Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetVisibleSources Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Nov 22 13:59:33 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:33+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 22 13:59:33 minidsp-shd go-librespot[2074]: time="2024-11-22T13:59:33+01:00" level=trace msg="emitting websocket event: volume" Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Nov 22 13:59:33 minidsp-shd volumio[661]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Nov 22 13:59:33 minidsp-shd volumio[661]: SPOTIFY: received: {"type":"volume","data":{"value":94,"max":100}} Nov 22 13:59:33 minidsp-shd volumio[661]: SPOTIFY: RECEIVED SPOTIFY VOLUME 94 Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Nov 22 13:59:33 minidsp-shd volumio[661]: info: Received Get System Info Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 22 13:59:33 minidsp-shd volumio[661]: info: Discovery: Getting this device information Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:33 minidsp-shd volumio[661]: info: Listing playlists Nov 22 13:59:33 minidsp-shd volumio[661]: info: Received Get System Info Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 22 13:59:33 minidsp-shd volumio[661]: info: Discovery: Getting this device information Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:33 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Nov 22 13:59:34 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:36 minidsp-shd volumio[661]: info: Executing endpoint metavolumio Nov 22 13:59:36 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Nov 22 13:59:36 minidsp-shd volumio[661]: info: Executing endpoint metavolumio Nov 22 13:59:36 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Nov 22 13:59:36 minidsp-shd volumio[661]: info: Executing endpoint metavolumio Nov 22 13:59:36 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 22 13:59:41 minidsp-shd volumio[661]: info: Retrieving Cloud Streaming UI Nov 22 13:59:41 minidsp-shd volumio[661]: info: Getting Tidal Cloud Configuration Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 22 13:59:41 minidsp-shd volumio[661]: info: Getting Qobuz Cloud Configuration Nov 22 13:59:41 minidsp-shd volumio[661]: info: Asking plugin for UI Config Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 22 13:59:41 minidsp-shd volumio[661]: info: Getting Spotify Cloud Configuration Nov 22 13:59:41 minidsp-shd volumio[661]: info: Asking plugin for UI Config Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 22 13:59:41 minidsp-shd volumio[661]: info: Saving Spotify Acccount Nov 22 13:59:41 minidsp-shd volumio[661]: info: Got it Nov 22 13:59:41 minidsp-shd volumio[661]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Nov 22 13:59:41 minidsp-shd volumio[661]: info: Got Tidal Cloud Configuration Nov 22 13:59:41 minidsp-shd volumio[661]: info: Got it Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetBrowseSources Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetBrowseSources Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetBrowseSources Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 22 13:59:41 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: mpd , updateDb Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand update Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:44 minidsp-shd volumio[661]: info: Nov 22 13:59:44 minidsp-shd volumio[661]: ---------------------------- MPD announces state update: update Nov 22 13:59:44 minidsp-shd volumio[661]: info: sendMpdCommand update took 12 milliseconds Nov 22 13:59:44 minidsp-shd volumio[661]: info: ControllerMpd::getState Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:44 minidsp-shd volumio[661]: info: Nov 22 13:59:44 minidsp-shd volumio[661]: ---------------------------- MPD announces state update: update Nov 22 13:59:44 minidsp-shd volumio[661]: info: ControllerMpd::getState Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:44 minidsp-shd volumio[661]: info: Nov 22 13:59:44 minidsp-shd volumio[661]: ---------------------------- MPD announces state update: update Nov 22 13:59:44 minidsp-shd volumio[661]: info: ControllerMpd::getState Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:44 minidsp-shd volumio[661]: info: Nov 22 13:59:44 minidsp-shd volumio[661]: ---------------------------- MPD announces state update: update Nov 22 13:59:44 minidsp-shd volumio[661]: info: ControllerMpd::getState Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:44 minidsp-shd volumio[661]: info: sendMpdCommand status took 18 milliseconds Nov 22 13:59:44 minidsp-shd volumio[661]: info: sendMpdCommand status took 12 milliseconds Nov 22 13:59:44 minidsp-shd volumio[661]: info: sendMpdCommand status took 11 milliseconds Nov 22 13:59:44 minidsp-shd volumio[661]: info: sendMpdCommand status took 9 milliseconds Nov 22 13:59:44 minidsp-shd volumio[661]: info: sendMpdCommand status took 9 milliseconds Nov 22 13:59:44 minidsp-shd volumio[661]: info: sendMpdCommand status took 7 milliseconds Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:44 minidsp-shd volumio[661]: info: Command Router : Notfying DB Updatefalse Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::Close All Modals sent Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:44 minidsp-shd volumio[661]: info: Command Router : Notfying DB Updatefalse Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::Close All Modals sent Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:44 minidsp-shd volumio[661]: info: Command Router : Notfying DB Updatefalse Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::Close All Modals sent Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:44 minidsp-shd volumio[661]: info: ControllerMpd::pushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::servicePushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:44 minidsp-shd volumio[661]: info: CorePlayQueue::getTrack 0 Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: CURRENT POSITION 0 Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::syncState stateService stop Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::syncState currentStatus pause Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:44 minidsp-shd volumio[661]: info: ControllerMpd::pushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::servicePushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:44 minidsp-shd volumio[661]: info: CorePlayQueue::getTrack 0 Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: CURRENT POSITION 0 Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::syncState stateService stop Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::syncState currentStatus pause Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:44 minidsp-shd volumio[661]: info: ControllerMpd::pushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::servicePushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:44 minidsp-shd volumio[661]: info: CorePlayQueue::getTrack 0 Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: CURRENT POSITION 0 Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::syncState stateService stop Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::syncState currentStatus pause Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:44 minidsp-shd volumio[661]: info: ------------------------------ 240ms Nov 22 13:59:44 minidsp-shd volumio[661]: info: ------------------------------ 234ms Nov 22 13:59:44 minidsp-shd volumio[661]: info: ------------------------------ 235ms Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:44 minidsp-shd volumio[661]: info: Nov 22 13:59:44 minidsp-shd volumio[661]: ---------------------------- MPD announces state update: update Nov 22 13:59:44 minidsp-shd volumio[661]: info: ControllerMpd::getState Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:44 minidsp-shd volumio[661]: info: Nov 22 13:59:44 minidsp-shd volumio[661]: ---------------------------- MPD announces state update: update Nov 22 13:59:44 minidsp-shd volumio[661]: info: ControllerMpd::getState Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:44 minidsp-shd volumio[661]: info: sendMpdCommand status took 244 milliseconds Nov 22 13:59:44 minidsp-shd volumio[661]: info: sendMpdCommand status took 242 milliseconds Nov 22 13:59:44 minidsp-shd volumio[661]: info: sendMpdCommand status took 11 milliseconds Nov 22 13:59:44 minidsp-shd volumio[661]: info: sendMpdCommand status took 9 milliseconds Nov 22 13:59:44 minidsp-shd volumio[661]: info: sendMpdCommand status took 8 milliseconds Nov 22 13:59:44 minidsp-shd volumio[661]: info: sendMpdCommand status took 7 milliseconds Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:44 minidsp-shd volumio[661]: info: Command Router : Notfying DB Updatefalse Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::Close All Modals sent Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:44 minidsp-shd volumio[661]: info: Command Router : Notfying DB Updatefalse Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::Close All Modals sent Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:44 minidsp-shd volumio[661]: info: Command Router : Notfying DB Updatefalse Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::Close All Modals sent Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:44 minidsp-shd volumio[661]: info: ControllerMpd::pushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::servicePushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:44 minidsp-shd volumio[661]: info: CorePlayQueue::getTrack 0 Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: CURRENT POSITION 0 Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::syncState stateService stop Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::syncState currentStatus pause Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:44 minidsp-shd volumio[661]: info: ControllerMpd::pushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::servicePushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:44 minidsp-shd volumio[661]: info: CorePlayQueue::getTrack 0 Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: CURRENT POSITION 0 Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::syncState stateService stop Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::syncState currentStatus pause Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:44 minidsp-shd volumio[661]: info: ControllerMpd::pushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::servicePushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:44 minidsp-shd volumio[661]: info: CorePlayQueue::getTrack 0 Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Nov 22 13:59:44 minidsp-shd volumio[661]: verbose: CURRENT POSITION 0 Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::syncState stateService stop Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::syncState currentStatus pause Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:44 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:44 minidsp-shd volumio[661]: info: ------------------------------ 424ms Nov 22 13:59:44 minidsp-shd volumio[661]: info: ------------------------------ 191ms Nov 22 13:59:44 minidsp-shd volumio[661]: info: ------------------------------ 189ms Nov 22 13:59:44 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:45 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:45 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:45 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:45 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:45 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:45 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:45 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:45 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:45 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:45 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:45 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:45 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 22 13:59:45 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: mpd , rescanDb Nov 22 13:59:45 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand rescan Nov 22 13:59:45 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:45 minidsp-shd volumio[661]: info: Nov 22 13:59:45 minidsp-shd volumio[661]: ---------------------------- MPD announces state update: update Nov 22 13:59:45 minidsp-shd volumio[661]: info: sendMpdCommand rescan took 6 milliseconds Nov 22 13:59:45 minidsp-shd volumio[661]: info: ControllerMpd::getState Nov 22 13:59:45 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:45 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:45 minidsp-shd volumio[661]: info: Nov 22 13:59:45 minidsp-shd volumio[661]: ---------------------------- MPD announces state update: update Nov 22 13:59:45 minidsp-shd volumio[661]: info: ControllerMpd::getState Nov 22 13:59:45 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:45 minidsp-shd volumio[661]: info: sendMpdCommand status took 5 milliseconds Nov 22 13:59:45 minidsp-shd volumio[661]: info: sendMpdCommand status took 3 milliseconds Nov 22 13:59:45 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:45 minidsp-shd volumio[661]: info: Command Router : Notfying DB Updatefalse Nov 22 13:59:45 minidsp-shd volumio[661]: info: CoreCommandRouter::Close All Modals sent Nov 22 13:59:45 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:45 minidsp-shd volumio[661]: info: ControllerMpd::pushState Nov 22 13:59:45 minidsp-shd volumio[661]: info: CoreCommandRouter::servicePushState Nov 22 13:59:45 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:45 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:45 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:45 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:45 minidsp-shd volumio[661]: info: CorePlayQueue::getTrack 0 Nov 22 13:59:45 minidsp-shd volumio[661]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Nov 22 13:59:45 minidsp-shd volumio[661]: verbose: CURRENT POSITION 0 Nov 22 13:59:45 minidsp-shd volumio[661]: info: CoreStateMachine::syncState stateService stop Nov 22 13:59:45 minidsp-shd volumio[661]: info: CoreStateMachine::syncState currentStatus pause Nov 22 13:59:45 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:45 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:45 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:45 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:45 minidsp-shd volumio[661]: info: ------------------------------ 77ms Nov 22 13:59:45 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:45 minidsp-shd volumio[661]: info: Nov 22 13:59:45 minidsp-shd volumio[661]: ---------------------------- MPD announces state update: update Nov 22 13:59:45 minidsp-shd volumio[661]: info: ControllerMpd::getState Nov 22 13:59:45 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:45 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:45 minidsp-shd volumio[661]: info: Nov 22 13:59:45 minidsp-shd volumio[661]: ---------------------------- MPD announces state update: update Nov 22 13:59:46 minidsp-shd volumio[661]: info: ControllerMpd::getState Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:46 minidsp-shd volumio[661]: info: sendMpdCommand status took 82 milliseconds Nov 22 13:59:46 minidsp-shd volumio[661]: info: sendMpdCommand status took 80 milliseconds Nov 22 13:59:46 minidsp-shd volumio[661]: info: sendMpdCommand status took 7 milliseconds Nov 22 13:59:46 minidsp-shd volumio[661]: info: sendMpdCommand status took 6 milliseconds Nov 22 13:59:46 minidsp-shd volumio[661]: info: sendMpdCommand status took 6 milliseconds Nov 22 13:59:46 minidsp-shd volumio[661]: info: sendMpdCommand status took 4 milliseconds Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:46 minidsp-shd volumio[661]: info: Command Router : Notfying DB Updatefalse Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::Close All Modals sent Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:46 minidsp-shd volumio[661]: info: Command Router : Notfying DB Updatefalse Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::Close All Modals sent Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:46 minidsp-shd volumio[661]: info: Command Router : Notfying DB Updatefalse Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::Close All Modals sent Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:46 minidsp-shd volumio[661]: info: ControllerMpd::pushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::servicePushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:46 minidsp-shd volumio[661]: info: CorePlayQueue::getTrack 0 Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: CURRENT POSITION 0 Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::syncState stateService stop Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::syncState currentStatus pause Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:46 minidsp-shd volumio[661]: info: ControllerMpd::pushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::servicePushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:46 minidsp-shd volumio[661]: info: CorePlayQueue::getTrack 0 Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: CURRENT POSITION 0 Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::syncState stateService stop Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::syncState currentStatus pause Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:46 minidsp-shd volumio[661]: info: ControllerMpd::pushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::servicePushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:46 minidsp-shd volumio[661]: info: CorePlayQueue::getTrack 0 Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: CURRENT POSITION 0 Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::syncState stateService stop Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::syncState currentStatus pause Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:46 minidsp-shd volumio[661]: info: ------------------------------ 287ms Nov 22 13:59:46 minidsp-shd volumio[661]: info: ------------------------------ 212ms Nov 22 13:59:46 minidsp-shd volumio[661]: info: ------------------------------ 210ms Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:46 minidsp-shd volumio[661]: info: Nov 22 13:59:46 minidsp-shd volumio[661]: ---------------------------- MPD announces state update: update Nov 22 13:59:46 minidsp-shd volumio[661]: info: ControllerMpd::getState Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:46 minidsp-shd volumio[661]: info: Nov 22 13:59:46 minidsp-shd volumio[661]: ---------------------------- MPD announces state update: update Nov 22 13:59:46 minidsp-shd volumio[661]: info: ControllerMpd::getState Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: ControllerMpd::sendMpdCommand status Nov 22 13:59:46 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:46 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:46 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:46 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:46 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:46 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:46 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:46 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:46 minidsp-shd volumio[661]: info: sendMpdCommand status took 77 milliseconds Nov 22 13:59:46 minidsp-shd volumio[661]: info: sendMpdCommand status took 75 milliseconds Nov 22 13:59:46 minidsp-shd volumio[661]: info: sendMpdCommand status took 75 milliseconds Nov 22 13:59:46 minidsp-shd volumio[661]: info: sendMpdCommand status took 74 milliseconds Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:46 minidsp-shd volumio[661]: info: Command Router : Notfying DB Updatefalse Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::Close All Modals sent Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:46 minidsp-shd volumio[661]: info: Command Router : Notfying DB Updatefalse Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::Close All Modals sent Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: ControllerMpd::parseState Nov 22 13:59:46 minidsp-shd volumio[661]: info: ControllerMpd::pushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::servicePushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:46 minidsp-shd volumio[661]: info: CorePlayQueue::getTrack 0 Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: CURRENT POSITION 0 Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::syncState stateService stop Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::syncState currentStatus pause Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:46 minidsp-shd volumio[661]: info: ControllerMpd::pushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::servicePushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:46 minidsp-shd volumio[661]: info: CorePlayQueue::getTrack 0 Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Nov 22 13:59:46 minidsp-shd volumio[661]: verbose: CURRENT POSITION 0 Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::syncState stateService stop Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::syncState currentStatus pause Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 13:59:46 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 13:59:46 minidsp-shd volumio[661]: info: ------------------------------ 209ms Nov 22 13:59:46 minidsp-shd volumio[661]: info: ------------------------------ 208ms Nov 22 13:59:46 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:46 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:46 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:46 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 13:59:49 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 22 13:59:52 minidsp-shd volumio[661]: info: Disabling MyMusic plugin bluetooth Nov 22 13:59:52 minidsp-shd sudo[2127]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumiobt.service Nov 22 13:59:52 minidsp-shd sudo[2127]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 13:59:52 minidsp-shd systemd[1]: Stopping Volumio Bluetooth Module... Nov 22 13:59:52 minidsp-shd volumio[661]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 22 13:59:52 minidsp-shd volumiobt[2129]: Killing pulse Nov 22 13:59:52 minidsp-shd volumiobt[2129]: Killing BT Pair agent Nov 22 13:59:52 minidsp-shd systemd[1]: volumiobt.service: Main process exited, code=killed, status=15/TERM Nov 22 13:59:52 minidsp-shd systemd[1]: volumiobt.service: Succeeded. Nov 22 13:59:52 minidsp-shd systemd[1]: Stopped Volumio Bluetooth Module. Nov 22 13:59:52 minidsp-shd sudo[2127]: pam_unix(sudo:session): session closed for user root Nov 22 13:59:52 minidsp-shd volumio[661]: info: Volumio BT Module successfully stopped Nov 22 13:59:52 minidsp-shd volumio[661]: info: Disabling plugin bluetooth Nov 22 13:59:52 minidsp-shd volumio[661]: info: Done. Nov 22 13:59:53 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 22 13:59:56 minidsp-shd volumio[661]: info: Disabling MyMusic plugin multiroom Nov 22 13:59:56 minidsp-shd volumio[661]: info: Disabling plugin multiroom Nov 22 13:59:56 minidsp-shd volumio[661]: info: Preparing to generate the ALSA configuration file Nov 22 13:59:56 minidsp-shd volumio[661]: info: Asound.conf file written Nov 22 13:59:56 minidsp-shd sudo[2133]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Nov 22 13:59:56 minidsp-shd sudo[2133]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 13:59:56 minidsp-shd sudo[2133]: pam_unix(sudo:session): session closed for user root Nov 22 13:59:56 minidsp-shd volumio[661]: xcb_connection_has_error() returned true Nov 22 13:59:56 minidsp-shd volumio[661]: info: Output device has changed, restarting MPD Nov 22 13:59:56 minidsp-shd sudo[2138]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 22 13:59:56 minidsp-shd sudo[2138]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 13:59:56 minidsp-shd sudo[2138]: pam_unix(sudo:session): session closed for user root Nov 22 13:59:56 minidsp-shd volumio[661]: info: Output device has changed, restarting Shairport Sync Nov 22 13:59:56 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 22 13:59:56 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 22 13:59:56 minidsp-shd sudo[2141]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 22 13:59:56 minidsp-shd sudo[2141]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 13:59:56 minidsp-shd systemd[1]: Stopping Music Player Daemon... Nov 22 13:59:56 minidsp-shd volumio[661]: xcb_connection_has_error() returned true Nov 22 13:59:56 minidsp-shd volumio[661]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 22 13:59:56 minidsp-shd volumio[661]: xcb_connection_has_error() returned true Nov 22 13:59:56 minidsp-shd volumio[661]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Nov 22 13:59:56 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 22 13:59:56 minidsp-shd volumio[661]: info: Reconfiguring and Restarting RAAT Plugin due to audio device changes Nov 22 13:59:56 minidsp-shd vtcs[1093]: [2024-11-22 13:59:56.799] [tisoc] [warning] [SessionManagerImpl.cpp:243] Illegal State: IDLE Nov 22 13:59:56 minidsp-shd vtcs[1093]: [2024-11-22 13:59:56.800] [tisoc] [error] [SpkconServer.cpp:382] recv error. client fd=8 errorno=104 error=Connection reset by peer Nov 22 13:59:56 minidsp-shd vtcs[1093]: [2024-11-22 13:59:56.800] [tisoc] [error] [SpkconServer.cpp:377] recv error. socket disconnected Nov 22 13:59:56 minidsp-shd volumio[661]: info: Done. Nov 22 13:59:56 minidsp-shd sudo[2149]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Nov 22 13:59:56 minidsp-shd sudo[2149]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 13:59:56 minidsp-shd systemd[1]: Stopping Volumio Tidal Connect Service... Nov 22 13:59:56 minidsp-shd systemd[1]: vtcs.service: Main process exited, code=killed, status=15/TERM Nov 22 13:59:56 minidsp-shd systemd[1]: vtcs.service: Succeeded. Nov 22 13:59:56 minidsp-shd systemd[1]: Stopped Volumio Tidal Connect Service. Nov 22 13:59:56 minidsp-shd volumio[661]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 22 13:59:56 minidsp-shd sudo[2152]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Nov 22 13:59:56 minidsp-shd sudo[2152]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 13:59:56 minidsp-shd sudo[2149]: pam_unix(sudo:session): session closed for user root Nov 22 13:59:56 minidsp-shd volumio[661]: info: MPD Permissions set Nov 22 13:59:56 minidsp-shd sudo[2152]: pam_unix(sudo:session): session closed for user root Nov 22 13:59:56 minidsp-shd volumio[661]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 22 13:59:56 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 22 13:59:56 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 22 13:59:56 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 22 13:59:56 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 22 13:59:56 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 22 13:59:56 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 22 13:59:56 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 22 13:59:56 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 22 13:59:57 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 22 13:59:57 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Nov 22 13:59:57 minidsp-shd systemd[1]: mpd.service: Succeeded. Nov 22 13:59:57 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 22 13:59:57 minidsp-shd systemd[1]: Stopped Music Player Daemon. Nov 22 13:59:57 minidsp-shd systemd[1]: Starting Music Player Daemon... Nov 22 13:59:57 minidsp-shd volumio[661]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Nov 22 13:59:57 minidsp-shd volumio[661]: info: Starting Shairport Sync Nov 22 13:59:57 minidsp-shd volumio[661]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 22 13:59:57 minidsp-shd sudo[2164]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 22 13:59:57 minidsp-shd sudo[2164]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 13:59:57 minidsp-shd systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 22 13:59:57 minidsp-shd systemd[1]: shairport-sync.service: Succeeded. Nov 22 13:59:57 minidsp-shd volumio[661]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 22 13:59:57 minidsp-shd systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 22 13:59:57 minidsp-shd volumio[661]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Nov 22 13:59:57 minidsp-shd systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 22 13:59:57 minidsp-shd sudo[2164]: pam_unix(sudo:session): session closed for user root Nov 22 13:59:57 minidsp-shd volumio[661]: info: Shairport-Sync Started Nov 22 13:59:57 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 22 13:59:57 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 22 13:59:57 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 22 13:59:57 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 22 13:59:57 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 22 13:59:57 minidsp-shd volumio[661]: info: Not Reporting Auto name since its the default one Nov 22 13:59:57 minidsp-shd volumio[661]: info: RAAT Overriding default device vendor model Nov 22 13:59:57 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Nov 22 13:59:57 minidsp-shd volumio[661]: xcb_connection_has_error() returned true Nov 22 13:59:57 minidsp-shd sudo[2176]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Nov 22 13:59:57 minidsp-shd sudo[2176]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 13:59:57 minidsp-shd systemd[1]: Stopping RAAT DAEMON... Nov 22 13:59:57 minidsp-shd systemd[1]: raat-daemon.service: Main process exited, code=killed, status=15/TERM Nov 22 13:59:57 minidsp-shd systemd[1]: raat-daemon.service: Succeeded. Nov 22 13:59:57 minidsp-shd systemd[1]: Stopped RAAT DAEMON. Nov 22 13:59:57 minidsp-shd volumio[661]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 22 13:59:57 minidsp-shd volumio[661]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Nov 22 13:59:57 minidsp-shd systemd[1]: Started RAAT DAEMON. Nov 22 13:59:57 minidsp-shd sudo[2176]: pam_unix(sudo:session): session closed for user root Nov 22 13:59:57 minidsp-shd volumio[661]: info: Raat Daemon started successfully Nov 22 13:59:57 minidsp-shd volumio[661]: info: Executing endpoint restartRAATSocket Nov 22 13:59:57 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: raat , establishDaemonConnection Nov 22 13:59:57 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 22 13:59:57 minidsp-shd volumio[661]: error: MPD error: Error: This socket has been ended by the other party Nov 22 13:59:57 minidsp-shd volumio[661]: error: This socket has been ended by the other party {"code":"EPIPE"} Nov 22 13:59:57 minidsp-shd volumio[661]: error: MPD error: Error: This socket has been ended by the other party Nov 22 13:59:57 minidsp-shd volumio[661]: error: This socket has been ended by the other party {"code":"EPIPE"} Nov 22 13:59:57 minidsp-shd volumio[661]: error: MPD error: Error: This socket has been ended by the other party Nov 22 13:59:57 minidsp-shd volumio[661]: error: This socket has been ended by the other party {"code":"EPIPE"} Nov 22 13:59:57 minidsp-shd volumio[661]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Nov 22 13:59:57 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioGetState Nov 22 13:59:59 minidsp-shd mpd[2162]: Nov 22 13:59 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 22 13:59:59 minidsp-shd systemd[1]: Started Music Player Daemon. Nov 22 13:59:59 minidsp-shd sudo[2141]: pam_unix(sudo:session): session closed for user root Nov 22 13:59:59 minidsp-shd volumio[661]: error: updateQueue error: null Nov 22 13:59:59 minidsp-shd volumio[661]: info: TidalConnect service stoped! Nov 22 13:59:59 minidsp-shd volumio[661]: info: TidalConnect service stoped! Nov 22 14:00:00 minidsp-shd volumio[661]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Nov 22 14:00:00 minidsp-shd volumio[661]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect Nov 22 14:00:00 minidsp-shd sudo[2200]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Nov 22 14:00:00 minidsp-shd sudo[2200]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 14:00:00 minidsp-shd systemd[1]: Started Volumio Tidal Connect Service. Nov 22 14:00:00 minidsp-shd sudo[2200]: pam_unix(sudo:session): session closed for user root Nov 22 14:00:00 minidsp-shd volumio[661]: info: Executing endpoint tc_getconfig Nov 22 14:00:00 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Nov 22 14:00:00 minidsp-shd vtcs[2202]: STARTING TidalConnect services, version: 1.3.0.19 Nov 22 14:00:00 minidsp-shd vtcs[2202]: STARTED TidalConnect services. Nov 22 14:00:00 minidsp-shd volumio[661]: info: Executing endpoint tc_connect Nov 22 14:00:00 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Nov 22 14:00:00 minidsp-shd volumio[661]: info: Connecting to TidalConnect Nov 22 14:00:00 minidsp-shd volumio[661]: info: CoreCommandRouter::servicePushState Nov 22 14:00:00 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 14:00:00 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 14:00:00 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 14:00:00 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 14:00:00 minidsp-shd volumio[661]: info: CorePlayQueue::getTrack 0 Nov 22 14:00:00 minidsp-shd volumio[661]: verbose: STATE SERVICE {"status":"stop","service":"tidalconnect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","icon":"fa fa-spinner","trackType":"tidal","codec":"","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","channels":2,"random":false,"repeat":false,"repeatSingle":false} Nov 22 14:00:00 minidsp-shd volumio[661]: verbose: CURRENT POSITION 0 Nov 22 14:00:00 minidsp-shd volumio[661]: info: CoreStateMachine::syncState stateService stop Nov 22 14:00:00 minidsp-shd volumio[661]: info: CoreStateMachine::syncState currentStatus pause Nov 22 14:00:00 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 14:00:00 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 22 14:00:00 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 14:00:00 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 14:00:00 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 14:00:00 minidsp-shd volumio[661]: info: CoreCommandRouter::servicePushState Nov 22 14:00:00 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 14:00:00 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 14:00:00 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 14:00:00 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 14:00:00 minidsp-shd volumio[661]: info: CorePlayQueue::getTrack 0 Nov 22 14:00:00 minidsp-shd volumio[661]: verbose: STATE SERVICE {"status":"stop","service":"tidalconnect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","icon":"fa fa-spinner","trackType":"tidal","codec":"","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","channels":2,"random":false,"repeat":false,"repeatSingle":false} Nov 22 14:00:00 minidsp-shd volumio[661]: verbose: CURRENT POSITION 0 Nov 22 14:00:00 minidsp-shd volumio[661]: info: CoreStateMachine::syncState stateService stop Nov 22 14:00:00 minidsp-shd volumio[661]: info: CoreStateMachine::syncState currentStatus pause Nov 22 14:00:00 minidsp-shd volumio[661]: info: CoreStateMachine::pushState Nov 22 14:00:00 minidsp-shd volumio[661]: info: CoreCommandRouter::volumioPushState Nov 22 14:00:00 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output update for this device Nov 22 14:00:00 minidsp-shd volumio[661]: info: MRS: Pushing multiroomSync output Nov 22 14:00:00 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 14:00:00 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 14:00:00 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 14:00:00 minidsp-shd volumio[661]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 22 14:00:01 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 22 14:00:02 minidsp-shd volumio[661]: info: Disabling MyMusic plugin upnp Nov 22 14:00:02 minidsp-shd sudo[2221]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop upmpdcli.service Nov 22 14:00:02 minidsp-shd sudo[2221]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 14:00:02 minidsp-shd systemd[1]: Stopping UPnP Renderer front-end to MPD... Nov 22 14:00:02 minidsp-shd volumio[661]: error: Upnp client error: Error: This socket has been ended by the other party Nov 22 14:00:02 minidsp-shd volumio[661]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 22 14:00:03 minidsp-shd volumio[661]: info: TidalConnect service started! Nov 22 14:00:03 minidsp-shd volumio[661]: info: Disabling MyMusic plugin metavolumio Nov 22 14:00:03 minidsp-shd volumio[661]: info: Removing METAVOLUMIO REST API Endpoints Nov 22 14:00:03 minidsp-shd volumio[661]: info: Removing metavolumio REST Endpoint Nov 22 14:00:03 minidsp-shd volumio[661]: info: Removing getSimilarArtists REST Endpoint Nov 22 14:00:03 minidsp-shd volumio[661]: info: Removing getSimilarAlbums REST Endpoint Nov 22 14:00:03 minidsp-shd volumio[661]: info: Removing getSimilarTracks REST Endpoint Nov 22 14:00:03 minidsp-shd volumio[661]: info: Disabling plugin metavolumio Nov 22 14:00:03 minidsp-shd volumio[661]: info: Done. Nov 22 14:00:05 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 22 14:00:06 minidsp-shd volumio[661]: info: Disabling MyMusic plugin upnp Nov 22 14:00:06 minidsp-shd sudo[2224]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop upmpdcli.service Nov 22 14:00:06 minidsp-shd sudo[2224]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 22 14:00:06 minidsp-shd volumio[661]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 22 14:00:09 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 22 14:00:10 minidsp-shd volumio[661]: info: Enabling MyMusic plugin upnp Nov 22 14:00:10 minidsp-shd volumio[661]: info: Enabling plugin upnp Nov 22 14:00:10 minidsp-shd volumio[661]: info: Loading plugin "upnp"... Nov 22 14:00:10 minidsp-shd volumio[661]: info: [1732280410220] Starting Upmpd Daemon Nov 22 14:00:10 minidsp-shd volumio[661]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 22 14:00:10 minidsp-shd volumio[661]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 22 14:00:10 minidsp-shd volumio[661]: Error: listen EADDRINUSE: address already in use :::6599 Nov 22 14:00:10 minidsp-shd volumio[661]: at Server.setupListenHandle [as _listen2] (net.js:1331:16) Nov 22 14:00:10 minidsp-shd volumio[661]: at listenInCluster (net.js:1379:12) Nov 22 14:00:10 minidsp-shd volumio[661]: at Server.listen (net.js:1465:7) Nov 22 14:00:10 minidsp-shd volumio[661]: at UpnpInterface.onVolumioStart (/volumio/app/plugins/audio_interface/upnp/index.js:78:17) Nov 22 14:00:10 minidsp-shd volumio[661]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:255:38) Nov 22 14:00:10 minidsp-shd volumio[661]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Nov 22 14:00:10 minidsp-shd volumio[661]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Nov 22 14:00:10 minidsp-shd volumio[661]: at processTicksAndRejections (internal/process/task_queues.js:77:11) { Nov 22 14:00:10 minidsp-shd volumio[661]: code: 'EADDRINUSE', Nov 22 14:00:10 minidsp-shd volumio[661]: errno: -98, Nov 22 14:00:10 minidsp-shd volumio[661]: syscall: 'listen', Nov 22 14:00:10 minidsp-shd volumio[661]: address: '::', Nov 22 14:00:10 minidsp-shd volumio[661]: port: 6599 Nov 22 14:00:10 minidsp-shd volumio[661]: } Nov 22 14:00:10 minidsp-shd volumio[661]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 22 14:00:11 minidsp-shd sudo[2236]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-22 13:59 Nov 22 14:00:11 minidsp-shd sudo[2236]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="17fcb754ddd6bd152b01008c46cc4ba1ca48bf35" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="281cefcd7a302aa7cfba569185cf7aae19b8c376" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="minidspshd" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 22 Mar 2024 03:00:28 PM CET" VOLUMIO_VERSION="3.608" VOLUMIO_HARDWARE="nanopineo2" VOLUMIO_DEVICENAME="NanoPi Neo2" VOLUMIO_VENDOR="miniDSP" VOLUMIO_MODEL="SHD" VOLUMIO_VENDOR_MODEL="miniDSP SHD" VOLUMIO_HASH="29ccfe8a9cff19911db4b736879ac117"