-- Logs begin at Tue 2025-09-16 14:44:11 CEST, end at Wed 2025-09-17 17:24:18 CEST. -- Sep 17 17:23:02 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Sep 17 17:23:02 volumio volumio[1230]: info: Listing playlists Sep 17 17:23:02 volumio volumio[1230]: info: Listing playlists Sep 17 17:23:06 volumio go-librespot[3856]: time="2025-09-17T17:23:06+02:00" level=trace msg="sent dealer ping" Sep 17 17:23:06 volumio go-librespot[3856]: time="2025-09-17T17:23:06+02:00" level=trace msg="received dealer pong" Sep 17 17:23:06 volumio go-librespot[3856]: time="2025-09-17T17:23:06+02:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1DXbtYAdenGE9U" Sep 17 17:23:06 volumio go-librespot[3856]: time="2025-09-17T17:23:06+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 137" Sep 17 17:23:10 volumio wpa_supplicant[1043]: wlan0: Failed to initiate sched scan Sep 17 17:23:12 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Sep 17 17:23:17 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 17 17:23:17 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 17 17:23:17 volumio volumio[1230]: info: Discovery: Getting this device information Sep 17 17:23:17 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Sep 17 17:23:17 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 17 17:23:20 volumio go-librespot[3856]: time="2025-09-17T17:23:20+02:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1E4lQCl7cBecSW" Sep 17 17:23:20 volumio go-librespot[3856]: time="2025-09-17T17:23:20+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 137" Sep 17 17:23:20 volumio wpa_supplicant[1043]: wlan0: Failed to initiate sched scan Sep 17 17:23:22 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Sep 17 17:23:22 volumio volumio[1230]: info: Listing playlists Sep 17 17:23:22 volumio volumio[1230]: info: Listing playlists Sep 17 17:23:29 volumio go-librespot[3856]: time="2025-09-17T17:23:29+02:00" level=debug msg="skipping dealer message" uri=playback-settings/content-settings-update Sep 17 17:23:29 volumio go-librespot[3856]: time="2025-09-17T17:23:29+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 159" Sep 17 17:23:30 volumio nmbd[871]: [2025/09/17 17:23:30.302929, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Sep 17 17:23:30 volumio nmbd[871]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.1.90 for name WORKGROUP<1d>. Sep 17 17:23:30 volumio nmbd[871]: This response was from IP 192.168.1.122, reporting an IP address of 192.168.1.122. Sep 17 17:23:31 volumio wpa_supplicant[1043]: wlan0: Failed to initiate sched scan Sep 17 17:23:32 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Sep 17 17:23:36 volumio go-librespot[3856]: time="2025-09-17T17:23:36+02:00" level=trace msg="sent dealer ping" Sep 17 17:23:36 volumio go-librespot[3856]: time="2025-09-17T17:23:36+02:00" level=trace msg="received dealer pong" Sep 17 17:23:36 volumio go-librespot[3856]: time="2025-09-17T17:23:36+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Sep 17 17:23:36 volumio go-librespot[3856]: time="2025-09-17T17:23:36+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 242" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=debug msg="handling transfer player command from 118cff581b58e6cfc82c4bd585c953c9c46c71c1" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=debug msg="resolved context of track" uri="spotify:album:6MCNMOCRsh6nxs7PNzc0zN" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=trace msg="fetched new page 0 with 15 items (list: 15)" uri="spotify:album:6MCNMOCRsh6nxs7PNzc0zN" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=debug msg="loading track (paused: false, position: 2506ms)" uri="spotify:track:5J221XVh7Kxg2bC4IWQ19n" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=trace msg="emitting websocket event: will_play" Sep 17 17:23:39 volumio volumio[1230]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5J221XVh7Kxg2bC4IWQ19n","play_origin":"album"}} Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 242" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=debug msg="selected format OGG_VORBIS_320 (a45bed399bdf8a6b7279d682fb1340aa3588198c)" uri="spotify:track:5J221XVh7Kxg2bC4IWQ19n" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=debug msg="requested aes key for file a45bed399bdf8a6b7279d682fb1340aa3588198c, gid: 5J221XVh7Kxg2bC4IWQ19n" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:5J221XVh7Kxg2bC4IWQ19n" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=debug msg="fetched first chunk of 26, total size is 13356184 bytes" uri="spotify:track:5J221XVh7Kxg2bC4IWQ19n" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=trace msg="seek to 2506ms (diff: 61ms, samples: 110514, bytes: 90853)" uri="spotify:track:5J221XVh7Kxg2bC4IWQ19n" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=debug msg="created new output device" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+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" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=info msg="loaded track \"If You Can't Say No\" (paused: false, position: 2506ms, duration: 317026ms, prefetched: false)" uri="spotify:track:5J221XVh7Kxg2bC4IWQ19n" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=debug msg="fetched chunk 3/25, size: 524288" uri="spotify:track:5J221XVh7Kxg2bC4IWQ19n" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=trace msg="scheduling prefetch in 285s" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=trace msg="emitting websocket event: metadata" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=trace msg="emitting websocket event: active" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=debug msg="sending successful reply for dealer request" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Sep 17 17:23:39 volumio volumio[1230]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5J221XVh7Kxg2bC4IWQ19n","name":"If You Can't Say No","artist_names":["Lenny Kravitz"],"album_name":"5","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02f1157b7dcd21bae0c2c75d89","position":2506,"duration":317026,"release_date":"year:1998 month:5 day:12","track_number":5,"disc_number":1}} Sep 17 17:23:39 volumio volumio[1230]: SPOTIFY: received: {"type":"active","data":null} Sep 17 17:23:39 volumio volumio[1230]: info: Aligning Spotify Volume to Volumio Volume Sep 17 17:23:39 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Sep 17 17:23:39 volumio volumio[1230]: info: Setting Spotify Volume from Volumio: 79 Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=trace msg="emitting websocket event: playing" Sep 17 17:23:39 volumio volumio[1230]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:5J221XVh7Kxg2bC4IWQ19n","resume":false,"play_origin":"album"}} Sep 17 17:23:39 volumio volumio[1230]: info: Spotify is playing in volatile mode Sep 17 17:23:39 volumio volumio[1230]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 17 17:23:39 volumio volumio[1230]: SPOTIFY: UNSET VOLATILE Sep 17 17:23:39 volumio volumio[1230]: SPOTIFY: {"status":"play","position":5,"title":"Eternity - ALEX WARREN","artist":null,"album":null,"albumart":"http://cdn-profiles.tunein.com/s87683/images/logoq.png?t=1","uri":"https://icecast-qmusicnl-cdp.triple-it.nl/Qmusic_nl_live.mp3?aw_0_1st.playerid=tunein","trackType":"webradio","seek":18304484,"duration":0,"samplerate":"","bitdepth":"","channels":2,"bitrate":"128 Kbps","random":null,"repeat":null,"repeatSingle":false,"consume":true,"volume":79,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":true,"updatedb":false,"volatile":false,"service":"webradio"} Sep 17 17:23:39 volumio volumio[1230]: info: Setting Spotify stop after unset volatile call Sep 17 17:23:39 volumio volumio[1230]: SPOTIFY: PUSH STATE SPOTIFY Sep 17 17:23:39 volumio volumio[1230]: SPOTIFY: {"status":"play","service":"spop","title":"If You Can't Say No","artist":"Lenny Kravitz","album":"5","albumart":"https://i.scdn.co/image/ab67616d00001e02f1157b7dcd21bae0c2c75d89","uri":"spotify:track:5J221XVh7Kxg2bC4IWQ19n","trackType":"spotify","seek":2506,"duration":317,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 17 17:23:39 volumio volumio[1230]: info: CoreCommandRouter::servicePushState Sep 17 17:23:39 volumio volumio[1230]: info: CoreStateMachine::pushState Sep 17 17:23:39 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 17 17:23:39 volumio volumio[1230]: info: CoreCommandRouter::volumioPushState Sep 17 17:23:39 volumio volumio[1230]: info: MRS: Pushing multiroomSync output update for this device Sep 17 17:23:39 volumio volumio[1230]: info: MRS: Pushing multiroomSync output Sep 17 17:23:39 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Sep 17 17:23:39 volumio volumio[1230]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=debug msg="fetched chunk 1/25, size: 524288" uri="spotify:track:5J221XVh7Kxg2bC4IWQ19n" Sep 17 17:23:39 volumio go-librespot[3856]: time="2025-09-17T17:23:39+02:00" level=debug msg="fetched chunk 2/25, size: 524288" uri="spotify:track:5J221XVh7Kxg2bC4IWQ19n" Sep 17 17:23:39 volumio volumio[1230]: SPOTIFY: PUSH STATE SPOTIFY Sep 17 17:23:39 volumio volumio[1230]: SPOTIFY: {"status":"play","service":"spop","title":"If You Can't Say No","artist":"Lenny Kravitz","album":"5","albumart":"https://i.scdn.co/image/ab67616d00001e02f1157b7dcd21bae0c2c75d89","uri":"spotify:track:5J221XVh7Kxg2bC4IWQ19n","trackType":"spotify","seek":2506,"duration":317,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 17 17:23:39 volumio volumio[1230]: info: CoreCommandRouter::servicePushState Sep 17 17:23:39 volumio volumio[1230]: info: CoreStateMachine::pushState Sep 17 17:23:39 volumio volumio[1230]: info: CoreCommandRouter::volumioPushState Sep 17 17:23:39 volumio volumio[1230]: info: MRS: Pushing multiroomSync output update for this device Sep 17 17:23:39 volumio volumio[1230]: info: MRS: Pushing multiroomSync output Sep 17 17:23:39 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Sep 17 17:23:39 volumio volumio[1230]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Sep 17 17:23:39 volumio volumio[1230]: info: Spotify Stop Sep 17 17:23:39 volumio volumio[1230]: SPOTIFY: SPOTIFY STOP Sep 17 17:23:39 volumio volumio[1230]: SPOTIFY: {"status":"play","title":"If You Can't Say No","artist":"Lenny Kravitz","album":"5","albumart":"https://i.scdn.co/image/ab67616d00001e02f1157b7dcd21bae0c2c75d89","uri":"spotify:track:5J221XVh7Kxg2bC4IWQ19n","trackType":"spotify","codec":"ogg","seek":2506,"duration":317,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":79,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true,"service":"spop"} Sep 17 17:23:40 volumio volumio[1230]: SPOTIFY: SETTING SPOTIFY VOLUME 79 Sep 17 17:23:40 volumio volumio[1230]: info: Sending Spotify command with payload to local API: /player/volume Sep 17 17:23:40 volumio go-librespot[3856]: time="2025-09-17T17:23:40+02:00" level=debug msg="update volume requested to 51772/65535" Sep 17 17:23:41 volumio go-librespot[3856]: time="2025-09-17T17:23:41+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 17 17:23:41 volumio go-librespot[3856]: time="2025-09-17T17:23:41+02:00" level=trace msg="emitting websocket event: volume" Sep 17 17:23:41 volumio volumio[1230]: SPOTIFY: received: {"type":"volume","data":{"value":79,"max":100}} Sep 17 17:23:41 volumio volumio[1230]: SPOTIFY: RECEIVED SPOTIFY VOLUME 79 Sep 17 17:23:42 volumio wpa_supplicant[1043]: wlan0: Failed to initiate sched scan Sep 17 17:23:42 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Sep 17 17:23:42 volumio volumio[1230]: info: Listing playlists Sep 17 17:23:42 volumio volumio[1230]: info: Listing playlists Sep 17 17:23:44 volumio go-librespot[3856]: time="2025-09-17T17:23:44+02:00" level=debug msg="update volume requested to 54394/65535" Sep 17 17:23:44 volumio go-librespot[3856]: time="2025-09-17T17:23:44+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 17 17:23:44 volumio go-librespot[3856]: time="2025-09-17T17:23:44+02:00" level=trace msg="emitting websocket event: volume" Sep 17 17:23:44 volumio volumio[1230]: SPOTIFY: received: {"type":"volume","data":{"value":83,"max":100}} Sep 17 17:23:44 volumio volumio[1230]: SPOTIFY: RECEIVED SPOTIFY VOLUME 83 Sep 17 17:23:44 volumio volumio[1230]: info: Setting Volumio Volume from Spotify: 83 Sep 17 17:23:44 volumio volumio[1230]: info: VolumeController::SetAlsaVolume83 Sep 17 17:23:44 volumio volumio[1230]: info: CoreStateMachine::pushState Sep 17 17:23:44 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 17 17:23:44 volumio volumio[1230]: info: CoreCommandRouter::volumioPushState Sep 17 17:23:44 volumio volumio[1230]: info: MRS: Pushing multiroomSync output update for this device Sep 17 17:23:44 volumio volumio[1230]: info: MRS: Pushing multiroomSync output Sep 17 17:23:44 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Sep 17 17:23:44 volumio volumio[1230]: SPOTIFY: RECEIVED VOLUMIO VOLUME 83 Sep 17 17:23:44 volumio go-librespot[3856]: time="2025-09-17T17:23:44+02:00" level=debug msg="update volume requested to 57015/65535" Sep 17 17:23:45 volumio go-librespot[3856]: time="2025-09-17T17:23:45+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 17 17:23:45 volumio go-librespot[3856]: time="2025-09-17T17:23:45+02:00" level=trace msg="emitting websocket event: volume" Sep 17 17:23:45 volumio volumio[1230]: SPOTIFY: received: {"type":"volume","data":{"value":87,"max":100}} Sep 17 17:23:45 volumio volumio[1230]: SPOTIFY: RECEIVED SPOTIFY VOLUME 87 Sep 17 17:23:45 volumio volumio[1230]: info: Setting Volumio Volume from Spotify: 87 Sep 17 17:23:45 volumio volumio[1230]: info: VolumeController::SetAlsaVolume87 Sep 17 17:23:45 volumio volumio[1230]: info: CoreStateMachine::pushState Sep 17 17:23:45 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 17 17:23:45 volumio volumio[1230]: info: CoreCommandRouter::volumioPushState Sep 17 17:23:45 volumio volumio[1230]: info: MRS: Pushing multiroomSync output update for this device Sep 17 17:23:45 volumio volumio[1230]: info: MRS: Pushing multiroomSync output Sep 17 17:23:45 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Sep 17 17:23:45 volumio volumio[1230]: SPOTIFY: RECEIVED VOLUMIO VOLUME 87 Sep 17 17:23:49 volumio go-librespot[3856]: time="2025-09-17T17:23:49+02:00" level=debug msg="fetched chunk 4/25, size: 524288" uri="spotify:track:5J221XVh7Kxg2bC4IWQ19n" Sep 17 17:23:52 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Sep 17 17:23:53 volumio wpa_supplicant[1043]: wlan0: Failed to initiate sched scan Sep 17 17:24:02 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Sep 17 17:24:02 volumio volumio[1230]: info: Listing playlists Sep 17 17:24:04 volumio wpa_supplicant[1043]: wlan0: Failed to initiate sched scan Sep 17 17:24:04 volumio go-librespot[3856]: time="2025-09-17T17:24:04+02:00" level=debug msg="fetched chunk 5/25, size: 524288" uri="spotify:track:5J221XVh7Kxg2bC4IWQ19n" Sep 17 17:24:06 volumio go-librespot[3856]: time="2025-09-17T17:24:06+02:00" level=trace msg="sent dealer ping" Sep 17 17:24:06 volumio go-librespot[3856]: time="2025-09-17T17:24:06+02:00" level=trace msg="received dealer pong" Sep 17 17:24:12 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Sep 17 17:24:14 volumio wpa_supplicant[1043]: wlan0: Failed to initiate sched scan Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=info msg="playback was transferred to iPhone" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=trace msg="closed output device because of stop command" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 242" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="put connect state inactive" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=trace msg="emitting websocket event: inactive" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=trace msg="emitting websocket event: stopped" Sep 17 17:24:15 volumio volumio[1230]: SPOTIFY: received: {"type":"inactive","data":null} Sep 17 17:24:15 volumio volumio[1230]: error: Failed to decode event: inactive Sep 17 17:24:15 volumio volumio[1230]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":""}} Sep 17 17:24:15 volumio volumio[1230]: SPOTIFY: PUSH STATE SPOTIFY Sep 17 17:24:15 volumio volumio[1230]: SPOTIFY: {"status":"stop","service":"spop","title":"If You Can't Say No","artist":"Lenny Kravitz","album":"5","albumart":"https://i.scdn.co/image/ab67616d00001e02f1157b7dcd21bae0c2c75d89","uri":"spotify:track:5J221XVh7Kxg2bC4IWQ19n","trackType":"spotify","seek":37506,"duration":317,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 17 17:24:15 volumio volumio[1230]: info: CoreCommandRouter::servicePushState Sep 17 17:24:15 volumio volumio[1230]: info: CoreStateMachine::pushState Sep 17 17:24:15 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 17 17:24:15 volumio volumio[1230]: info: CoreCommandRouter::volumioPushState Sep 17 17:24:15 volumio volumio[1230]: info: MRS: Pushing multiroomSync output update for this device Sep 17 17:24:15 volumio volumio[1230]: info: MRS: Pushing multiroomSync output Sep 17 17:24:15 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Sep 17 17:24:15 volumio volumio[1230]: info: CorePlayQueue::getTrack 5 Sep 17 17:24:15 volumio volumio[1230]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current soundcloud Received spop Sep 17 17:24:15 volumio volumio[1230]: SPOTIFY: RECEIVED VOLUMIO VOLUME 87 Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="dealer connection closed" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="dealer recv loop stopped" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="obtained new client token: AACb6EHQL4qvMhzm9if0u6AX4pGhSxkXxxS7SL4PHaRMjPthW83ezfjN+RaonJ79+iOlK1S8zGnR5ZRadtjLI/N2dhcO+Rnz4cRzSPKlBf8NeG+lvuABPLfA1rTAyLeqY71818WLWY7/IYK1F7dssPjE53nezECKJHdWkeClM8tvqdyiZcT3yhPKsB2VZEwmmM5+3ys06w266IgrpGnrJrxLBri9zkH0+Z7/BaNwGT4lNcR/vFhY" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+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]" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="completed keyexchange" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="completed challenge" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=info msg="authenticated AP" username="11*****30" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=info msg="authenticated Login5" username="11*****30" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="restored session after logout" username="11*****30" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="dealer connection opened" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=trace msg="starting accesspoint recv loop" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=trace msg="starting dealer recv loop" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=trace msg="received accesspoint ping" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="received connection id: NzNkZjFkNWUtOWQy...QTA5QjY2NDYxOQ==" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=trace msg="received accesspoint pong ack" Sep 17 17:24:15 volumio go-librespot[3856]: time="2025-09-17T17:24:15+02:00" level=debug msg="put connect state because NEW_DEVICE" Sep 17 17:24:18 volumio volumio[1230]: info: MRS: STARTING volumioStreaming Sep 17 17:24:18 volumio sudo[10344]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/stream.m3u8 /tmp/hls/stream31.ts /tmp/hls/stream32.ts /tmp/hls/stream33.ts /tmp/hls/stream34.ts /tmp/hls/stream35.ts Sep 17 17:24:18 volumio sudo[10344]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 17 17:24:18 volumio sudo[10344]: pam_unix(sudo:session): session closed for user root Sep 17 17:24:18 volumio volumio[1230]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 17 17:24:18 volumio volumio[1230]: TypeError: Cannot read property 'send' of null Sep 17 17:24:18 volumio volumio[1230]: at Client.send (/myvolumio/plugins/audio_interface/multiroom/node_modules/castv2/lib/client.js:128:11) Sep 17 17:24:18 volumio volumio[1230]: at Channel.send (/myvolumio/plugins/audio_interface/multiroom/node_modules/castv2/lib/channel.js:34:12) Sep 17 17:24:18 volumio volumio[1230]: at fn.Controller.send (/myvolumio/plugins/audio_interface/multiroom/node_modules/castv2-client/lib/controllers/controller.js:28:16) Sep 17 17:24:18 volumio volumio[1230]: at fn.RequestResponseController.request (/myvolumio/plugins/audio_interface/multiroom/node_modules/castv2-client/lib/controllers/request-response.js:34:8) Sep 17 17:24:18 volumio volumio[1230]: at fn.MediaController.sessionRequest (/myvolumio/plugins/audio_interface/multiroom/node_modules/castv2-client/lib/controllers/media.js:91:8) Sep 17 17:24:18 volumio volumio[1230]: at fn.MediaController.stop (/myvolumio/plugins/audio_interface/multiroom/node_modules/castv2-client/lib/controllers/media.js:107:8) Sep 17 17:24:18 volumio volumio[1230]: at DefaultMediaReceiver.stop (/myvolumio/plugins/audio_interface/multiroom/node_modules/castv2-client/lib/senders/default-media-receiver.js:42:19) Sep 17 17:24:18 volumio volumio[1230]: at Timeout._onTimeout (/myvolumio/plugins/audio_interface/multiroom/multiroom_real:1:5038) Sep 17 17:24:18 volumio volumio[1230]: at listOnTimeout (internal/timers.js:554:17) Sep 17 17:24:18 volumio volumio[1230]: at processTimers (internal/timers.js:497:7) Sep 17 17:24:18 volumio volumio[1230]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 17 17:24:18 volumio sudo[10347]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumioStreaming Sep 17 17:24:18 volumio sudo[10347]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 17 17:24:18 volumio systemd[1]: Stopping VolumioStreamingService... Sep 17 17:24:18 volumio systemd[1]: volumioStreaming.service: Main process exited, code=killed, status=15/TERM Sep 17 17:24:18 volumio systemd[1]: volumioStreaming.service: Succeeded. Sep 17 17:24:18 volumio systemd[1]: Stopped VolumioStreamingService. Sep 17 17:24:18 volumio systemd[1]: Started VolumioStreamingService. Sep 17 17:24:18 volumio sudo[10358]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Sep 17 17:24:18 volumio sudo[10358]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 17 17:24:18 volumio sudo[10347]: pam_unix(sudo:session): session closed for user root Sep 17 17:24:18 volumio sudo[10358]: pam_unix(sudo:session): session closed for user root Sep 17 17:24:18 volumio go-librespot[3856]: time="2025-09-17T17:24:18+02:00" level=debug msg="handling transfer player command from 118cff581b58e6cfc82c4bd585c953c9c46c71c1" Sep 17 17:24:18 volumio sudo[10362]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-09-17 17:23 Sep 17 17:24:18 volumio sudo[10362]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 17 17:24:18 volumio go-librespot[3856]: time="2025-09-17T17:24:18+02:00" level=debug msg="resolved context of track" uri="spotify:album:6MCNMOCRsh6nxs7PNzc0zN" Sep 17 17:24:18 volumio go-librespot[3856]: time="2025-09-17T17:24:18+02:00" level=trace msg="fetched new page 0 with 15 items (list: 15)" uri="spotify:album:6MCNMOCRsh6nxs7PNzc0zN" Sep 17 17:24:18 volumio go-librespot[3856]: time="2025-09-17T17:24:18+02:00" level=debug msg="loading track (paused: false, position: 41432ms)" uri="spotify:track:5J221XVh7Kxg2bC4IWQ19n" 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="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"