-- Logs begin at Wed 2025-04-30 11:53:41 CEST, end at Fri 2025-05-09 12:22:09 CEST. -- May 09 12:21:00 volumio-raspi-1 volumio[691]: info: Listing playlists May 09 12:21:00 volumio-raspi-1 volumio[691]: info: Listing playlists May 09 12:21:00 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::volumioGetVisibleSources May 09 12:21:00 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 09 12:21:00 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::volumioGetState May 09 12:21:00 volumio-raspi-1 volumio[691]: info: CorePlayQueue::getTrack 0 May 09 12:21:00 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 09 12:21:00 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 09 12:21:00 volumio-raspi-1 volumio[691]: info: Received Get System Info May 09 12:21:00 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 09 12:21:00 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 09 12:21:00 volumio-raspi-1 volumio[691]: info: Discovery: Getting this device information May 09 12:21:00 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::volumioGetState May 09 12:21:00 volumio-raspi-1 volumio[691]: info: CorePlayQueue::getTrack 0 May 09 12:21:00 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 09 12:21:00 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::volumioGetState May 09 12:21:00 volumio-raspi-1 volumio[691]: info: CorePlayQueue::getTrack 0 May 09 12:21:01 volumio-raspi-1 volumio[691]: info: Listing playlists May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::volumioGetState May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CorePlayQueue::getTrack 0 May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 09 12:21:01 volumio-raspi-1 volumio[691]: info: Received Get System Info May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 09 12:21:01 volumio-raspi-1 volumio[691]: info: Discovery: Getting this device information May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::volumioGetState May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CorePlayQueue::getTrack 0 May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates May 09 12:21:01 volumio-raspi-1 volumio[691]: info: Received Get System Version May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 09 12:21:01 volumio-raspi-1 volumio[691]: info: Received Get System Info May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 09 12:21:01 volumio-raspi-1 volumio[691]: info: Discovery: Getting this device information May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::volumioGetState May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CorePlayQueue::getTrack 0 May 09 12:21:01 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 09 12:21:01 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:01+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 09 12:21:01 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:01+02: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]" May 09 12:21:01 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:01+02: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]" May 09 12:21:01 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:01+02:00" level=info msg="zeroconf server listening on port 39649" May 09 12:21:02 volumio-raspi-1 volumio[691]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 09 12:21:02 volumio-raspi-1 volumio[691]: SPOTIFY: BQAehLV-WI1g3rQf_a-pBhdW6QKxiWv-U1YD8dFZpgZnUk-bb7vIQYBSHnU57egEdFWyFb6-5OTLtiW8yyBT4tBJwZjGDZUfVPNeH7qTAESpwjQEZnBtUR7a7YNR3nPxDQiFtAfejN8CJtRcx4I9nWCrlJK-Wpa_aKXxizKlpXU_-HTu5LWjJlv5xOUsY7mojM-g6j1T8DTdhwMGHFmXNCQW8-17NCdZumEJlGsZRyR1ez7tZ3R7VZdGM5Ld3F5OZipcFJ93rqUY1FrE-WOp7qQBxYw May 09 12:21:02 volumio-raspi-1 volumio[691]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 09 12:21:02 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:02+02:00" level=debug msg="obtained new client token: AADqFIUxEFJ2RtvOx2r0nzmFTpGgXK1QyyZFWFhxceAG9hvMwPv/kYwB2MKt1hXHuhltxY+jRTiE8wN8OSfWNHmt9YmloxKWK3PPMH0ASEueOvIMfWRe1CoG8hmXz4d494ykk47GG2j7CTSk7WaAlSzOyiKKUOVdXoXQx7rgHM4UIJv1H2luflFeNzWSjU0292QrsucJAL2FSiigFdMH4pr7O4lcTUp4a4YHbAJygFfag3KuYkX75Mg=" May 09 12:21:02 volumio-raspi-1 volumio[691]: info: New Spotify access token = BQAehLV-WI1g3rQf_a-pBhdW6QKxiWv-U1YD8dFZpgZnUk-bb7vIQYBSHnU57egEdFWyFb6-5OTLtiW8yyBT4tBJwZjGDZUfVPNeH7qTAESpwjQEZnBtUR7a7YNR3nPxDQiFtAfejN8CJtRcx4I9nWCrlJK-Wpa_aKXxizKlpXU_-HTu5LWjJlv5xOUsY7mojM-g6j1T8DTdhwMGHFmXNCQW8-17NCdZumEJlGsZRyR1ez7tZ3R7VZdGM5Ld3F5OZipcFJ93rqUY1FrE-WOp7qQBxYw May 09 12:21:02 volumio-raspi-1 volumio[691]: info: Spotify credentials grant success - running version from March 24, 2019 May 09 12:21:02 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:02+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" May 09 12:21:02 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:02+02:00" level=debug msg="completed keyexchange" May 09 12:21:02 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:02+02:00" level=debug msg="completed challenge" May 09 12:21:02 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken May 09 12:21:02 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:02+02:00" level=info msg="authenticated AP as michbak-10" May 09 12:21:02 volumio-raspi-1 volumio[691]: verbose: New Socket.io Connection to 192.168.181.78 from 192.168.181.21 UA: Mozilla/5.0 (Linux; Android 14; SM-S911B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/135.0.7049.111 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 May 09 12:21:02 volumio-raspi-1 volumio[691]: info: go-librespot daemon successfully initialized May 09 12:21:02 volumio-raspi-1 volumio[691]: info: Starting Shairport Sync May 09 12:21:03 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:03+02:00" level=info msg="authenticated Login5 as michbak-10" May 09 12:21:03 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:03+02:00" level=debug msg="initializing zeroconf session, username: michbak-10" May 09 12:21:03 volumio-raspi-1 volumio[691]: info: Starting Shairport Sync May 09 12:21:03 volumio-raspi-1 volumio[691]: info: Starting Shairport Sync May 09 12:21:03 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:03+02:00" level=debug msg="dealer connection opened" May 09 12:21:03 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:03+02:00" level=trace msg="starting accesspoint recv loop" May 09 12:21:03 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:03+02:00" level=trace msg="starting dealer recv loop" May 09 12:21:03 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:03+02:00" level=trace msg="received accesspoint ping" May 09 12:21:03 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:03+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 09 12:21:03 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:03+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 09 12:21:03 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:03+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 09 12:21:03 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:03+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 09 12:21:03 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:03+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 09 12:21:03 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:03+02:00" level=trace msg="received accesspoint pong ack" May 09 12:21:03 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:03+02:00" level=debug msg="received connection id: ZTU2YTRkNzAtYmI5Ny00NzFjLTk2YmMtZmEzMjA5Y2E3ZTY5K2RlYWxlcit0Y3A6Ly8wYWNhNThjMy5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArOTVBOTNEMTNCMjhFMTIzNzA2RThDMzM5OTRCOEJDN0FEMDgyNUU2RTI2RjZERDI4NDIyMkRDMzg0OUY5OUFDMw==" May 09 12:21:03 volumio-raspi-1 sudo[1155]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 09 12:21:04 volumio-raspi-1 sudo[1155]: pam_unix(sudo:session): session opened for user root by (uid=0) May 09 12:21:04 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:04+02:00" level=debug msg="put connect state because NEW_DEVICE" May 09 12:21:04 volumio-raspi-1 sudo[1157]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 09 12:21:04 volumio-raspi-1 sudo[1157]: pam_unix(sudo:session): session opened for user root by (uid=0) May 09 12:21:04 volumio-raspi-1 systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 09 12:21:04 volumio-raspi-1 systemd[1]: shairport-sync.service: Succeeded. May 09 12:21:04 volumio-raspi-1 systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 09 12:21:04 volumio-raspi-1 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 09 12:21:05 volumio-raspi-1 sudo[1160]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 09 12:21:05 volumio-raspi-1 sudo[1160]: pam_unix(sudo:session): session opened for user root by (uid=0) May 09 12:21:05 volumio-raspi-1 sudo[1155]: pam_unix(sudo:session): session closed for user root May 09 12:21:05 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::volumioGetState May 09 12:21:05 volumio-raspi-1 systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 09 12:21:05 volumio-raspi-1 systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM May 09 12:21:05 volumio-raspi-1 volumio[691]: info: CorePlayQueue::getTrack 0 May 09 12:21:05 volumio-raspi-1 systemd[1]: shairport-sync.service: Succeeded. May 09 12:21:05 volumio-raspi-1 systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 09 12:21:05 volumio-raspi-1 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 09 12:21:05 volumio-raspi-1 sudo[1157]: pam_unix(sudo:session): session closed for user root May 09 12:21:06 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:06+02:00" level=debug msg="handling transfer player command from 13d5ad7613de84b2909da48298eed7a3650c5c7a" May 09 12:21:06 volumio-raspi-1 volumio[691]: info: Initializing connection to go-librespot Websocket May 09 12:21:06 volumio-raspi-1 systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 09 12:21:06 volumio-raspi-1 systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM May 09 12:21:06 volumio-raspi-1 systemd[1]: shairport-sync.service: Succeeded. May 09 12:21:06 volumio-raspi-1 systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 09 12:21:06 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:06+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DWUW2bvSkjcJ6" May 09 12:21:06 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:06+02:00" level=trace msg="fetched new page 0 with 80 items (list: 80)" uri="spotify:playlist:37i9dQZF1DWUW2bvSkjcJ6" May 09 12:21:06 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:06+02:00" level=debug msg="loading track (paused: false, position: 377314ms)" uri="spotify:track:20kaCbdgkJRUPniPVZgsoR" May 09 12:21:06 volumio-raspi-1 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 09 12:21:06 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard May 09 12:21:06 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:06+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 09 12:21:06 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:06+02:00" level=trace msg="emitting websocket event: will_play" May 09 12:21:06 volumio-raspi-1 sudo[1160]: pam_unix(sudo:session): session closed for user root May 09 12:21:06 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:06+02:00" level=debug msg="selected format OGG_VORBIS_160 (09dd85ec411a03b90ead6550d0e5e7dc85bc90c8)" uri="spotify:track:20kaCbdgkJRUPniPVZgsoR" May 09 12:21:06 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:06+02:00" level=debug msg="requested aes key for file 09dd85ec411a03b90ead6550d0e5e7dc85bc90c8, gid: 20kaCbdgkJRUPniPVZgsoR" May 09 12:21:08 volumio-raspi-1 volumio[691]: verbose: New Socket.io Connection to 192.168.181.78 from 192.168.181.21 UA: Mozilla/5.0 (Linux; Android 14; SM-S911B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/135.0.7049.111 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 May 09 12:21:08 volumio-raspi-1 volumio[691]: info: Shairport-Sync Started May 09 12:21:08 volumio-raspi-1 volumio[691]: Error adding Membership: Error: addMembership EINVAL May 09 12:21:08 volumio-raspi-1 volumio[691]: info: Shairport-Sync Started May 09 12:21:08 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:08+02:00" level=debug msg="fetched first chunk of 6, total size is 2791150 bytes" uri="spotify:track:20kaCbdgkJRUPniPVZgsoR" May 09 12:21:08 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings May 09 12:21:09 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:09+02:00" level=debug msg="new websocket client" May 09 12:21:09 volumio-raspi-1 volumio[691]: info: Shairport-Sync Started May 09 12:21:10 volumio-raspi-1 volumio[691]: info: Connection to go-librespot Websocket established May 09 12:21:10 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::volumioGetState May 09 12:21:10 volumio-raspi-1 volumio[691]: info: CorePlayQueue::getTrack 0 May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar May 09 12:21:10 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:10+02:00" level=debug msg="fetched chunk 2/5, size: 524288" uri="spotify:track:20kaCbdgkJRUPniPVZgsoR" May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso May 09 12:21:10 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso May 09 12:21:11 volumio-raspi-1 volumio[691]: info: Adding plugin bluetooth to MyMusic Plugins May 09 12:21:11 volumio-raspi-1 volumio[691]: info: Adding plugin multiroom to MyMusic Plugins May 09 12:21:11 volumio-raspi-1 volumio[691]: info: Adding plugin metavolumio to MyMusic Plugins May 09 12:21:11 volumio-raspi-1 volumio[691]: info: Adding plugin cd_controller to MyMusic Plugins May 09 12:21:11 volumio-raspi-1 volumio[691]: info: Adding plugin qobuzconnect to MyMusic Plugins May 09 12:21:11 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:11+02:00" level=debug msg="fetched chunk 5/5, size: 169710" uri="spotify:track:20kaCbdgkJRUPniPVZgsoR" May 09 12:21:11 volumio-raspi-1 volumio[691]: info: Adding plugin smart_inputs to MyMusic Plugins May 09 12:21:11 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:11+02:00" level=trace msg="seek to 136615ms (diff: 136440ms, samples: 6024721, bytes: 2779617)" uri="spotify:track:20kaCbdgkJRUPniPVZgsoR" May 09 12:21:11 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:11+02:00" level=debug msg="created new output device" May 09 12:21:11 volumio-raspi-1 volumio[691]: info: Adding plugin tidalconnect to MyMusic Plugins May 09 12:21:11 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... May 09 12:21:12 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:12+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 250" May 09 12:21:12 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:12+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1316" May 09 12:21:12 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:12+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" May 09 12:21:12 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:12+02:00" level=info msg="loaded track \"Won’t Be Possible\" (paused: false, position: 377314ms, duration: 136615ms, prefetched: false)" uri="spotify:track:20kaCbdgkJRUPniPVZgsoR" May 09 12:21:12 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:12+02:00" level=debug msg="vorbis: corrupt or missing data in bitstream" uri="spotify:track:20kaCbdgkJRUPniPVZgsoR" May 09 12:21:12 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:12+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 09 12:21:12 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:12+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1342" May 09 12:21:13 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:13+02:00" level=debug msg="fetched chunk 1/5, size: 524288" uri="spotify:track:20kaCbdgkJRUPniPVZgsoR" May 09 12:21:13 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:13+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 09 12:21:13 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:13+02:00" level=debug msg="fetched chunk 3/5, size: 524288" uri="spotify:track:20kaCbdgkJRUPniPVZgsoR" May 09 12:21:13 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:13+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1119" May 09 12:21:13 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:13+02:00" level=trace msg="emitting websocket event: metadata" May 09 12:21:13 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:13+02:00" level=trace msg="emitting websocket event: active" May 09 12:21:13 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:13+02:00" level=debug msg="prefetching next track" uri="spotify:track:31P3lzjtP65naJF9LLnY2n" May 09 12:21:13 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:13+02:00" level=debug msg="sending successful reply for dealer request" May 09 12:21:13 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:13+02:00" level=debug msg="selected format OGG_VORBIS_160 (0e0f9c52cb4ba7fd0f33ec5f02bb6694c480b4e1)" uri="spotify:track:31P3lzjtP65naJF9LLnY2n" May 09 12:21:13 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:13+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 09 12:21:13 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:13+02:00" level=trace msg="emitting websocket event: playing" May 09 12:21:13 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:13+02:00" level=trace msg="emitting websocket event: not_playing" May 09 12:21:13 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:13+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:31P3lzjtP65naJF9LLnY2n" May 09 12:21:13 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:13+02:00" level=debug msg="requested aes key for file 0e0f9c52cb4ba7fd0f33ec5f02bb6694c480b4e1, gid: 31P3lzjtP65naJF9LLnY2n" May 09 12:21:13 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:13+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 09 12:21:13 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:13+02:00" level=trace msg="emitting websocket event: will_play" May 09 12:21:13 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:13+02:00" level=debug msg="selected format OGG_VORBIS_160 (0e0f9c52cb4ba7fd0f33ec5f02bb6694c480b4e1)" uri="spotify:track:31P3lzjtP65naJF9LLnY2n" May 09 12:21:13 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:13+02:00" level=debug msg="requested aes key for file 0e0f9c52cb4ba7fd0f33ec5f02bb6694c480b4e1, gid: 31P3lzjtP65naJF9LLnY2n" May 09 12:21:15 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:15+02:00" level=debug msg="fetched first chunk of 6, total size is 3125637 bytes" uri="spotify:track:31P3lzjtP65naJF9LLnY2n" May 09 12:21:15 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:15+02:00" level=debug msg="fetched first chunk of 6, total size is 3125637 bytes" uri="spotify:track:31P3lzjtP65naJF9LLnY2n" May 09 12:21:15 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:15+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" May 09 12:21:16 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:16+02:00" level=info msg="prefetched track \"Who Knows\" (duration: 171124ms)" uri="spotify:track:31P3lzjtP65naJF9LLnY2n" May 09 12:21:16 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:16+02:00" level=info msg="loaded track \"Who Knows\" (paused: false, position: 0ms, duration: 171124ms, prefetched: false)" uri="spotify:track:31P3lzjtP65naJF9LLnY2n" May 09 12:21:17 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:17+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 09 12:21:17 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:17+02:00" level=trace msg="scheduling prefetch in 141s" May 09 12:21:17 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:17+02:00" level=trace msg="emitting websocket event: metadata" May 09 12:21:19 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:19+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 09 12:21:19 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:19+02:00" level=trace msg="emitting websocket event: playing" May 09 12:21:19 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:19+02:00" level=debug msg="fetched chunk 2/5, size: 524288" uri="spotify:track:31P3lzjtP65naJF9LLnY2n" May 09 12:21:20 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:20+02:00" level=debug msg="fetched chunk 3/5, size: 524288" uri="spotify:track:31P3lzjtP65naJF9LLnY2n" May 09 12:21:22 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:22+02:00" level=debug msg="fetched chunk 3/5, size: 524288" uri="spotify:track:31P3lzjtP65naJF9LLnY2n" May 09 12:21:22 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:22+02:00" level=debug msg="fetched chunk 1/5, size: 524288" uri="spotify:track:31P3lzjtP65naJF9LLnY2n" May 09 12:21:22 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:22+02:00" level=debug msg="fetched chunk 2/5, size: 524288" uri="spotify:track:31P3lzjtP65naJF9LLnY2n" May 09 12:21:22 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:22+02:00" level=debug msg="fetched chunk 1/5, size: 524288" uri="spotify:track:31P3lzjtP65naJF9LLnY2n" May 09 12:21:23 volumio-raspi-1 mpd[1125]: May 09 12:21 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 09 12:21:23 volumio-raspi-1 systemd[1]: Started Music Player Daemon. May 09 12:21:23 volumio-raspi-1 mpd_monitor.sh[391]: MPD Monitor Service: MPD restarted due to no mpc output. May 09 12:21:25 volumio-raspi-1 volumio-remote-updater[371]: [2025-05-09 12:21:25] [disconnect] Disconnect close local:[1008,Pong timeout] remote:[1006] May 09 12:21:30 volumio-raspi-1 volumio-remote-updater[371]: [2025-05-09 12:21:30] [connect] Successful connection May 09 12:21:32 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded May 09 12:21:32 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio May 09 12:21:32 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 09 12:21:32 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 09 12:21:32 volumio-raspi-1 volumio[691]: info: Starting MyVolumio Remote Streaming Endpoints May 09 12:21:33 volumio-raspi-1 volumio[691]: info: MyVolumio login type: Token May 09 12:21:33 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started May 09 12:21:33 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... May 09 12:21:33 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:33+02:00" level=trace msg="sent dealer ping" May 09 12:21:33 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:33+02:00" level=trace msg="received dealer pong" May 09 12:21:42 volumio-raspi-1 volumio-remote-updater[371]: [2025-05-09 12:21:42] [connect] Successful connection May 09 12:21:43 volumio-raspi-1 volumiologrotate[399]: ls: cannot access '/var/log/samba/log.wb-VOLUMIO': No such file or directory May 09 12:21:43 volumio-raspi-1 volumiologrotate[399]: ls: cannot access 'RASPI': No such file or directory May 09 12:21:43 volumio-raspi-1 volumiologrotate[399]: ls: cannot access '1': No such file or directory May 09 12:21:48 volumio-raspi-1 volumio[691]: info: Starting Streaming Service Transparent Proxy May 09 12:21:48 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded May 09 12:21:48 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services May 09 12:21:48 volumio-raspi-1 volumio[691]: info: Streaming services startup May 09 12:21:48 volumio-raspi-1 volumio[691]: info: Starting Streaming Daemon May 09 12:21:49 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:21:49+02:00" level=debug msg="fetched chunk 4/5, size: 524288" uri="spotify:track:31P3lzjtP65naJF9LLnY2n" May 09 12:21:50 volumio-raspi-1 sudo[1292]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service May 09 12:21:50 volumio-raspi-1 sudo[1292]: pam_unix(sudo:session): session opened for user root by (uid=0) May 09 12:21:50 volumio-raspi-1 volumio[691]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started May 09 12:21:50 volumio-raspi-1 sudo[1292]: pam_unix(sudo:session): session closed for user root May 09 12:21:52 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard May 09 12:21:53 volumio-raspi-1 volumio[691]: info: Getting Spotify volume May 09 12:21:53 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 09 12:21:53 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 09 12:21:53 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 09 12:21:53 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 09 12:21:54 volumio-raspi-1 volumio[691]: info: Listing playlists May 09 12:21:54 volumio-raspi-1 volumio[691]: info: Listing playlists May 09 12:21:54 volumio-raspi-1 volumio[691]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:20kaCbdgkJRUPniPVZgsoR","name":"Won’t Be Possible","artist_names":["Tiësto","Odd Mob","Goodboys"],"album_name":"Won’t Be Possible","album_cover_url":"https://i.scdn.co/image/ab67616d00001e022cff9e8b9fae97beb4225de2","position":377314,"duration":136615,"release_date":"year:2025 month:5 day:9","track_number":1,"disc_number":1}} May 09 12:21:54 volumio-raspi-1 volumio[691]: SPOTIFY: received: {"type":"active","data":null} May 09 12:21:54 volumio-raspi-1 volumio[691]: info: Aligning Spotify Volume to Volumio Volume May 09 12:21:54 volumio-raspi-1 volumio[691]: info: CoreCommandRouter::volumioGetState May 09 12:21:54 volumio-raspi-1 volumio[691]: info: CorePlayQueue::getTrack 0 May 09 12:21:54 volumio-raspi-1 volumio[691]: info: Setting Spotify Volume from Volumio: 36 May 09 12:21:54 volumio-raspi-1 volumio[691]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:20kaCbdgkJRUPniPVZgsoR","play_origin":"playlist"}} May 09 12:21:54 volumio-raspi-1 volumio[691]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 09 12:21:54 volumio-raspi-1 volumio[691]: TypeError: Cannot read property 'service' of undefined May 09 12:21:54 volumio-raspi-1 volumio[691]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:340:50) May 09 12:21:54 volumio-raspi-1 volumio[691]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:266:18) May 09 12:21:54 volumio-raspi-1 volumio[691]: at WebSocket.message (/data/plugins/music_service/spop/index.js:193:14) May 09 12:21:54 volumio-raspi-1 volumio[691]: at WebSocket.emit (events.js:315:20) May 09 12:21:54 volumio-raspi-1 volumio[691]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) May 09 12:21:54 volumio-raspi-1 volumio[691]: at Receiver.emit (events.js:315:20) May 09 12:21:54 volumio-raspi-1 volumio[691]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) May 09 12:21:54 volumio-raspi-1 volumio[691]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) May 09 12:21:54 volumio-raspi-1 volumio[691]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) May 09 12:21:54 volumio-raspi-1 volumio[691]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) May 09 12:21:54 volumio-raspi-1 volumio[691]: at writeOrBuffer (internal/streams/writable.js:358:12) May 09 12:21:54 volumio-raspi-1 volumio[691]: at Receiver.Writable.write (internal/streams/writable.js:303:10) May 09 12:21:54 volumio-raspi-1 volumio[691]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) May 09 12:21:54 volumio-raspi-1 volumio[691]: at Socket.emit (events.js:315:20) May 09 12:21:54 volumio-raspi-1 volumio[691]: at addChunk (internal/streams/readable.js:309:12) May 09 12:21:54 volumio-raspi-1 volumio[691]: at readableAddChunk (internal/streams/readable.js:284:9) May 09 12:21:54 volumio-raspi-1 volumio[691]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 09 12:21:57 volumio-raspi-1 volumio-remote-updater[371]: [2025-05-09 12:21:57] [connect] Successful connection May 09 12:22:03 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:03+02:00" level=trace msg="sent dealer ping" May 09 12:22:03 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:03+02:00" level=trace msg="received dealer pong" May 09 12:22:05 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:05+02:00" level=debug msg="handling skip_next player command from webapi-ed38f5077f8646e4bc7fa386963d816e" May 09 12:22:05 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:05+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1N9SGRAf3N9phdOWak2A1p" May 09 12:22:05 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:05+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 09 12:22:05 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:05+02:00" level=trace msg="emitting websocket event: will_play" May 09 12:22:05 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:05+02:00" level=debug msg="selected format OGG_VORBIS_160 (a906612ce766832c2dfde838a64c66fe208dcbfb)" uri="spotify:track:1N9SGRAf3N9phdOWak2A1p" May 09 12:22:05 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:05+02:00" level=debug msg="requested aes key for file a906612ce766832c2dfde838a64c66fe208dcbfb, gid: 1N9SGRAf3N9phdOWak2A1p" May 09 12:22:06 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:06+02:00" level=debug msg="fetched first chunk of 7, total size is 3401351 bytes" uri="spotify:track:1N9SGRAf3N9phdOWak2A1p" May 09 12:22:07 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:07+02:00" level=info msg="loaded track \"ADAC\" (paused: false, position: 0ms, duration: 173440ms, prefetched: false)" uri="spotify:track:1N9SGRAf3N9phdOWak2A1p" May 09 12:22:07 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:07+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 09 12:22:07 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:07+02:00" level=trace msg="scheduling prefetch in 143s" May 09 12:22:07 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:07+02:00" level=trace msg="emitting websocket event: metadata" May 09 12:22:07 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:07+02:00" level=debug msg="sending successful reply for dealer request" May 09 12:22:08 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:08+02:00" level=debug msg="fetched chunk 3/6, size: 524288" uri="spotify:track:1N9SGRAf3N9phdOWak2A1p" May 09 12:22:08 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 09 12:22:08 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:08+02:00" level=trace msg="emitting websocket event: playing" May 09 12:22:09 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:09+02:00" level=debug msg="fetched chunk 1/6, size: 524288" uri="spotify:track:1N9SGRAf3N9phdOWak2A1p" May 09 12:22:09 volumio-raspi-1 sudo[1333]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-09 12:21 May 09 12:22:09 volumio-raspi-1 sudo[1333]: pam_unix(sudo:session): session opened for user root by (uid=0) May 09 12:22:09 volumio-raspi-1 go-librespot[1139]: time="2025-05-09T12:22:09+02:00" level=debug msg="fetched chunk 2/6, size: 524288" uri="spotify:track:1N9SGRAf3N9phdOWak2A1p" PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="9ab87de061b3649c303da550e73c92d340b0f989" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 30 Apr 2025 11:47:57 AM CEST" VOLUMIO_VERSION="3.807" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fddd10196af80fdc784c726185a6abe4"