-- Logs begin at Tue 2025-10-21 14:29:54 EEST, end at Sat 2025-10-25 17:17:46 EEST. -- Oct 25 17:16:01 rivoplus go-librespot[12097]: time="2025-10-25T17:16:01+03:00" level=trace msg="sent dealer ping" Oct 25 17:16:01 rivoplus go-librespot[12097]: time="2025-10-25T17:16:01+03:00" level=trace msg="received dealer pong" Oct 25 17:16:02 rivoplus go-librespot[12097]: time="2025-10-25T17:16:02+03:00" level=debug msg="handling skip_prev player command from 676d30de84555655040ae3f52b213259f4843093" Oct 25 17:16:02 rivoplus go-librespot[12097]: time="2025-10-25T17:16:02+03:00" level=debug msg="skip previous track" Oct 25 17:16:02 rivoplus go-librespot[12097]: time="2025-10-25T17:16:02+03:00" level=debug msg="loading track (paused: true, position: 0ms)" uri="spotify:track:2QSuqxALyh7JFoQEBxyo0H" Oct 25 17:16:02 rivoplus go-librespot[12097]: time="2025-10-25T17:16:02+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 25 17:16:02 rivoplus go-librespot[12097]: time="2025-10-25T17:16:02+03:00" level=trace msg="emitting websocket event: will_play" Oct 25 17:16:02 rivoplus volumio[3110]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:album:2vtMi0d0613jhp85klO9eb","uri":"spotify:track:2QSuqxALyh7JFoQEBxyo0H","play_origin":""}} Oct 25 17:16:02 rivoplus go-librespot[12097]: time="2025-10-25T17:16:02+03:00" level=debug msg="selected format OGG_VORBIS_320 (d66b1a09c302d122171ab8d97d7ebc966bc56bd4)" uri="spotify:track:2QSuqxALyh7JFoQEBxyo0H" Oct 25 17:16:02 rivoplus go-librespot[12097]: time="2025-10-25T17:16:02+03:00" level=debug msg="requested aes key for file d66b1a09c302d122171ab8d97d7ebc966bc56bd4, gid: 2QSuqxALyh7JFoQEBxyo0H" Oct 25 17:16:02 rivoplus go-librespot[12097]: time="2025-10-25T17:16:02+03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:2QSuqxALyh7JFoQEBxyo0H" Oct 25 17:16:02 rivoplus go-librespot[12097]: time="2025-10-25T17:16:02+03:00" level=debug msg="fetched first chunk of 29, total size is 14963704 bytes" uri="spotify:track:2QSuqxALyh7JFoQEBxyo0H" Oct 25 17:16:02 rivoplus go-librespot[12097]: time="2025-10-25T17:16:02+03:00" level=info msg="loaded track \"I Robot\" (paused: true, position: 0ms, duration: 360773ms, prefetched: false)" uri="spotify:track:2QSuqxALyh7JFoQEBxyo0H" Oct 25 17:16:02 rivoplus go-librespot[12097]: time="2025-10-25T17:16:02+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 25 17:16:02 rivoplus go-librespot[12097]: time="2025-10-25T17:16:02+03:00" level=trace msg="emitting websocket event: metadata" Oct 25 17:16:02 rivoplus go-librespot[12097]: time="2025-10-25T17:16:02+03:00" level=debug msg="sending successful reply for dealer request" Oct 25 17:16:02 rivoplus volumio[3110]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2QSuqxALyh7JFoQEBxyo0H","name":"I Robot","artist_names":["The Alan Parsons Project"],"album_name":"I Robot","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02a20cc321ff5017259984266b","position":0,"duration":360773,"release_date":"year:1977 month:7 day:8","track_number":1,"disc_number":1}} Oct 25 17:16:02 rivoplus go-librespot[12097]: time="2025-10-25T17:16:02+03:00" level=debug msg="fetched chunk 1/28, size: 524288" uri="spotify:track:2QSuqxALyh7JFoQEBxyo0H" Oct 25 17:16:02 rivoplus go-librespot[12097]: time="2025-10-25T17:16:02+03:00" level=debug msg="fetched chunk 3/28, size: 524288" uri="spotify:track:2QSuqxALyh7JFoQEBxyo0H" Oct 25 17:16:02 rivoplus go-librespot[12097]: time="2025-10-25T17:16:02+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 25 17:16:02 rivoplus go-librespot[12097]: time="2025-10-25T17:16:02+03:00" level=trace msg="emitting websocket event: paused" Oct 25 17:16:02 rivoplus volumio[3110]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:album:2vtMi0d0613jhp85klO9eb","uri":"spotify:track:2QSuqxALyh7JFoQEBxyo0H","play_origin":""}} Oct 25 17:16:02 rivoplus volumio[3110]: SPOTIFY: PUSH STATE SPOTIFY Oct 25 17:16:02 rivoplus volumio[3110]: SPOTIFY: {"status":"pause","service":"spop","title":"I Robot","artist":"The Alan Parsons Project","album":"I Robot","albumart":"https://i.scdn.co/image/ab67616d00001e02a20cc321ff5017259984266b","uri":"spotify:track:2QSuqxALyh7JFoQEBxyo0H","trackType":"spotify","seek":0,"duration":360,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 25 17:16:02 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:16:02 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:16:02 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 17:16:02 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:16:02 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:16:03 rivoplus go-librespot[12097]: time="2025-10-25T17:16:03+03:00" level=debug msg="fetched chunk 2/28, size: 524288" uri="spotify:track:2QSuqxALyh7JFoQEBxyo0H" Oct 25 17:16:03 rivoplus go-librespot[12097]: time="2025-10-25T17:16:03+03:00" level=debug msg="handling resume player command from 676d30de84555655040ae3f52b213259f4843093" Oct 25 17:16:03 rivoplus go-librespot[12097]: time="2025-10-25T17:16:03+03:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:2QSuqxALyh7JFoQEBxyo0H" Oct 25 17:16:03 rivoplus go-librespot[12097]: time="2025-10-25T17:16:03+03:00" level=warning msg="failed handling dealer request" error="failed starting playback: ALSA error at snd_pcm_open: Device or resource busy" Oct 25 17:16:05 rivoplus volumio[3110]: info: Executing endpoint metavolumio Oct 25 17:16:05 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 25 17:16:05 rivoplus volumio[3110]: info: Executing endpoint metavolumio Oct 25 17:16:05 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 25 17:16:05 rivoplus volumio[3110]: info: Executing endpoint metavolumio Oct 25 17:16:05 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 25 17:16:11 rivoplus volumio[3110]: verbose: New Socket.io Connection to 192.168.50.86 from 192.168.50.231 UA: Mozilla/5.0 (Linux; Android 15; SM-S911B Build/AP3A.240905.015.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/141.0.7390.97 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Oct 25 17:16:11 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 25 17:16:11 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetVisibleSources Oct 25 17:16:11 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 25 17:16:11 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:16:11 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 25 17:16:11 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 25 17:16:11 rivoplus volumio[3110]: info: Received Get System Info Oct 25 17:16:11 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 25 17:16:11 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 25 17:16:11 rivoplus volumio[3110]: info: Discovery: Getting this device information Oct 25 17:16:11 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:16:11 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 25 17:16:11 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:16:11 rivoplus volumio[3110]: info: Listing playlists Oct 25 17:16:11 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 25 17:16:11 rivoplus go-librespot[12097]: time="2025-10-25T17:16:11+03:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1DX0XUsuxWHRQd" Oct 25 17:16:11 rivoplus go-librespot[12097]: time="2025-10-25T17:16:11+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 137" Oct 25 17:16:16 rivoplus go-librespot[12097]: time="2025-10-25T17:16:16+03:00" level=debug msg="handling resume player command from 676d30de84555655040ae3f52b213259f4843093" Oct 25 17:16:16 rivoplus go-librespot[12097]: time="2025-10-25T17:16:16+03:00" level=debug msg="vorbis: corrupt or missing data in bitstream" uri="spotify:track:2QSuqxALyh7JFoQEBxyo0H" Oct 25 17:16:16 rivoplus go-librespot[12097]: time="2025-10-25T17:16:16+03:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:2QSuqxALyh7JFoQEBxyo0H" Oct 25 17:16:16 rivoplus go-librespot[12097]: time="2025-10-25T17:16:16+03:00" level=warning msg="failed handling dealer request" error="failed starting playback: ALSA error at snd_pcm_open: Device or resource busy" Oct 25 17:16:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioVolatilePlay Oct 25 17:16:16 rivoplus volumio[3110]: info: CoreStateMachine::volatilePlay Oct 25 17:16:16 rivoplus volumio[3110]: info: Spotify Play Oct 25 17:16:16 rivoplus volumio[3110]: info: Sending Spotify command to local API: /player/resume Oct 25 17:16:16 rivoplus go-librespot[12097]: time="2025-10-25T17:16:16+03:00" level=debug msg="vorbis: corrupt or missing data in bitstream" uri="spotify:track:2QSuqxALyh7JFoQEBxyo0H" Oct 25 17:16:16 rivoplus go-librespot[12097]: time="2025-10-25T17:16:16+03:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:2QSuqxALyh7JFoQEBxyo0H" Oct 25 17:16:20 rivoplus go-librespot[12097]: time="2025-10-25T17:16:20+03:00" level=debug msg="handling skip_next player command from 676d30de84555655040ae3f52b213259f4843093" Oct 25 17:16:20 rivoplus go-librespot[12097]: time="2025-10-25T17:16:20+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4sCCZW0ezEPAexAidFsoVm" Oct 25 17:16:21 rivoplus go-librespot[12097]: time="2025-10-25T17:16:21+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 25 17:16:21 rivoplus go-librespot[12097]: time="2025-10-25T17:16:21+03:00" level=trace msg="emitting websocket event: will_play" Oct 25 17:16:21 rivoplus volumio[3110]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:album:2vtMi0d0613jhp85klO9eb","uri":"spotify:track:4sCCZW0ezEPAexAidFsoVm","play_origin":""}} Oct 25 17:16:21 rivoplus go-librespot[12097]: time="2025-10-25T17:16:21+03:00" level=debug msg="selected format OGG_VORBIS_320 (2f82a6096426301d93c1d0035491ede30e816f8e)" uri="spotify:track:4sCCZW0ezEPAexAidFsoVm" Oct 25 17:16:21 rivoplus go-librespot[12097]: time="2025-10-25T17:16:21+03:00" level=debug msg="requested aes key for file 2f82a6096426301d93c1d0035491ede30e816f8e, gid: 4sCCZW0ezEPAexAidFsoVm" Oct 25 17:16:21 rivoplus go-librespot[12097]: time="2025-10-25T17:16:21+03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4sCCZW0ezEPAexAidFsoVm" Oct 25 17:16:21 rivoplus go-librespot[12097]: time="2025-10-25T17:16:21+03:00" level=debug msg="fetched first chunk of 16, total size is 8246720 bytes" uri="spotify:track:4sCCZW0ezEPAexAidFsoVm" Oct 25 17:16:21 rivoplus go-librespot[12097]: time="2025-10-25T17:16:21+03:00" level=warning msg="failed handling dealer request" error="failed skipping to next track: failed loading current track (advance to spotify:track:4sCCZW0ezEPAexAidFsoVm): failed setting stream for spotify:track:4sCCZW0ezEPAexAidFsoVm: ALSA error at snd_pcm_open: Device or resource busy" Oct 25 17:16:21 rivoplus go-librespot[12097]: time="2025-10-25T17:16:21+03:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:4sCCZW0ezEPAexAidFsoVm" Oct 25 17:16:21 rivoplus go-librespot[12097]: time="2025-10-25T17:16:21+03:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:4sCCZW0ezEPAexAidFsoVm" Oct 25 17:16:21 rivoplus go-librespot[12097]: time="2025-10-25T17:16:21+03:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:4sCCZW0ezEPAexAidFsoVm" Oct 25 17:16:29 rivoplus go-librespot[12097]: time="2025-10-25T17:16:29+03:00" level=debug msg="handling pause player command from 676d30de84555655040ae3f52b213259f4843093" Oct 25 17:16:29 rivoplus go-librespot[12097]: time="2025-10-25T17:16:29+03:00" level=debug msg="pause track at 0ms" Oct 25 17:16:29 rivoplus go-librespot[12097]: time="2025-10-25T17:16:29+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 25 17:16:29 rivoplus go-librespot[12097]: time="2025-10-25T17:16:29+03:00" level=debug msg="sending successful reply for dealer request" Oct 25 17:16:29 rivoplus go-librespot[12097]: time="2025-10-25T17:16:29+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 25 17:16:29 rivoplus go-librespot[12097]: time="2025-10-25T17:16:29+03:00" level=trace msg="emitting websocket event: paused" Oct 25 17:16:29 rivoplus volumio[3110]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:album:2vtMi0d0613jhp85klO9eb","uri":"spotify:track:4sCCZW0ezEPAexAidFsoVm","play_origin":""}} Oct 25 17:16:29 rivoplus volumio[3110]: SPOTIFY: PUSH STATE SPOTIFY Oct 25 17:16:29 rivoplus volumio[3110]: SPOTIFY: {"status":"pause","service":"spop","title":"I Robot","artist":"The Alan Parsons Project","album":"I Robot","albumart":"https://i.scdn.co/image/ab67616d00001e02a20cc321ff5017259984266b","uri":"spotify:track:2QSuqxALyh7JFoQEBxyo0H","trackType":"spotify","seek":0,"duration":360,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 25 17:16:29 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:16:29 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:16:29 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:16:29 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:16:31 rivoplus go-librespot[12097]: time="2025-10-25T17:16:31+03:00" level=trace msg="sent dealer ping" Oct 25 17:16:31 rivoplus go-librespot[12097]: time="2025-10-25T17:16:31+03:00" level=trace msg="received dealer pong" Oct 25 17:16:40 rivoplus volumio[3110]: info: CoreCommandRouter::volumioNext Oct 25 17:16:40 rivoplus volumio[3110]: info: CoreStateMachine::next Oct 25 17:16:40 rivoplus volumio[3110]: info: Spotify next Oct 25 17:16:40 rivoplus volumio[3110]: info: Sending Spotify command to local API: /player/next Oct 25 17:16:40 rivoplus go-librespot[12097]: time="2025-10-25T17:16:40+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4vGwwMIIvFHtm4KX0rqF0U" Oct 25 17:16:41 rivoplus go-librespot[12097]: time="2025-10-25T17:16:41+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 25 17:16:41 rivoplus go-librespot[12097]: time="2025-10-25T17:16:41+03:00" level=trace msg="emitting websocket event: will_play" Oct 25 17:16:41 rivoplus volumio[3110]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:album:2vtMi0d0613jhp85klO9eb","uri":"spotify:track:4vGwwMIIvFHtm4KX0rqF0U","play_origin":""}} Oct 25 17:16:41 rivoplus go-librespot[12097]: time="2025-10-25T17:16:41+03:00" level=debug msg="selected format OGG_VORBIS_320 (82bb335f74ce90df31383b1802ec4a6f63339f90)" uri="spotify:track:4vGwwMIIvFHtm4KX0rqF0U" Oct 25 17:16:41 rivoplus go-librespot[12097]: time="2025-10-25T17:16:41+03:00" level=debug msg="requested aes key for file 82bb335f74ce90df31383b1802ec4a6f63339f90, gid: 4vGwwMIIvFHtm4KX0rqF0U" Oct 25 17:16:41 rivoplus go-librespot[12097]: time="2025-10-25T17:16:41+03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4vGwwMIIvFHtm4KX0rqF0U" Oct 25 17:16:41 rivoplus go-librespot[12097]: time="2025-10-25T17:16:41+03:00" level=debug msg="fetched first chunk of 20, total size is 10155876 bytes" uri="spotify:track:4vGwwMIIvFHtm4KX0rqF0U" Oct 25 17:16:41 rivoplus go-librespot[12097]: time="2025-10-25T17:16:41+03:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:4vGwwMIIvFHtm4KX0rqF0U" Oct 25 17:16:41 rivoplus go-librespot[12097]: time="2025-10-25T17:16:41+03:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:4vGwwMIIvFHtm4KX0rqF0U" Oct 25 17:16:41 rivoplus go-librespot[12097]: time="2025-10-25T17:16:41+03:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:4vGwwMIIvFHtm4KX0rqF0U" Oct 25 17:16:44 rivoplus volumio[3110]: info: CoreCommandRouter::volumioVolatilePlay Oct 25 17:16:44 rivoplus volumio[3110]: info: CoreStateMachine::volatilePlay Oct 25 17:16:44 rivoplus volumio[3110]: info: Spotify Play Oct 25 17:16:44 rivoplus volumio[3110]: info: Sending Spotify command to local API: /player/resume Oct 25 17:16:44 rivoplus go-librespot[12097]: time="2025-10-25T17:16:44+03:00" level=trace msg="seek to 3383ms (diff: 131ms, samples: 149190, bytes: 128162)" uri="spotify:track:4vGwwMIIvFHtm4KX0rqF0U" Oct 25 17:16:47 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPrevious Oct 25 17:16:47 rivoplus volumio[3110]: info: Spotify previous Oct 25 17:16:47 rivoplus volumio[3110]: info: Sending Spotify command to local API: /player/prev Oct 25 17:16:47 rivoplus go-librespot[12097]: time="2025-10-25T17:16:47+03:00" level=debug msg="seek track to 0ms" Oct 25 17:16:47 rivoplus go-librespot[12097]: time="2025-10-25T17:16:47+03:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:4vGwwMIIvFHtm4KX0rqF0U" Oct 25 17:16:47 rivoplus volumio[3110]: info: CoreCommandRouter::volumioNext Oct 25 17:16:47 rivoplus volumio[3110]: info: CoreStateMachine::next Oct 25 17:16:47 rivoplus volumio[3110]: info: Spotify next Oct 25 17:16:47 rivoplus volumio[3110]: info: Sending Spotify command to local API: /player/next Oct 25 17:16:47 rivoplus go-librespot[12097]: time="2025-10-25T17:16:47+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 25 17:16:47 rivoplus go-librespot[12097]: time="2025-10-25T17:16:47+03:00" level=trace msg="scheduling prefetch in 216s" Oct 25 17:16:47 rivoplus go-librespot[12097]: time="2025-10-25T17:16:47+03:00" level=trace msg="emitting websocket event: seek" Oct 25 17:16:47 rivoplus go-librespot[12097]: time="2025-10-25T17:16:47+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1OdDILKk5pxLektkU9XGKZ" Oct 25 17:16:47 rivoplus volumio[3110]: SPOTIFY: received: {"type":"seek","data":{"context_uri":"spotify:album:2vtMi0d0613jhp85klO9eb","uri":"spotify:track:4vGwwMIIvFHtm4KX0rqF0U","position":0,"duration":245693,"play_origin":""}} Oct 25 17:16:47 rivoplus volumio[3110]: SPOTIFY: PUSH STATE SPOTIFY Oct 25 17:16:47 rivoplus volumio[3110]: SPOTIFY: {"status":"pause","service":"spop","title":"I Robot","artist":"The Alan Parsons Project","album":"I Robot","albumart":"https://i.scdn.co/image/ab67616d00001e02a20cc321ff5017259984266b","uri":"spotify:track:2QSuqxALyh7JFoQEBxyo0H","trackType":"spotify","seek":0,"duration":360,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 25 17:16:47 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:16:47 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:16:47 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:16:47 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:16:48 rivoplus go-librespot[12097]: time="2025-10-25T17:16:48+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 25 17:16:48 rivoplus go-librespot[12097]: time="2025-10-25T17:16:48+03:00" level=trace msg="emitting websocket event: will_play" Oct 25 17:16:48 rivoplus volumio[3110]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:album:2vtMi0d0613jhp85klO9eb","uri":"spotify:track:1OdDILKk5pxLektkU9XGKZ","play_origin":""}} Oct 25 17:16:48 rivoplus go-librespot[12097]: time="2025-10-25T17:16:48+03:00" level=debug msg="selected format OGG_VORBIS_320 (1ceea66e3d315d0c175a1ffefb6c1617c6ad2722)" uri="spotify:track:1OdDILKk5pxLektkU9XGKZ" Oct 25 17:16:48 rivoplus go-librespot[12097]: time="2025-10-25T17:16:48+03:00" level=debug msg="requested aes key for file 1ceea66e3d315d0c175a1ffefb6c1617c6ad2722, gid: 1OdDILKk5pxLektkU9XGKZ" Oct 25 17:16:48 rivoplus go-librespot[12097]: time="2025-10-25T17:16:48+03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:1OdDILKk5pxLektkU9XGKZ" Oct 25 17:16:48 rivoplus go-librespot[12097]: time="2025-10-25T17:16:48+03:00" level=debug msg="fetched first chunk of 19, total size is 9839280 bytes" uri="spotify:track:1OdDILKk5pxLektkU9XGKZ" Oct 25 17:16:48 rivoplus go-librespot[12097]: time="2025-10-25T17:16:48+03:00" level=debug msg="fetched chunk 1/18, size: 524288" uri="spotify:track:1OdDILKk5pxLektkU9XGKZ" Oct 25 17:16:48 rivoplus go-librespot[12097]: time="2025-10-25T17:16:48+03:00" level=debug msg="fetched chunk 2/18, size: 524288" uri="spotify:track:1OdDILKk5pxLektkU9XGKZ" Oct 25 17:16:48 rivoplus go-librespot[12097]: time="2025-10-25T17:16:48+03:00" level=debug msg="fetched chunk 3/18, size: 524288" uri="spotify:track:1OdDILKk5pxLektkU9XGKZ" Oct 25 17:16:51 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetQueue Oct 25 17:16:51 rivoplus volumio[3110]: info: CoreStateMachine::getQueue Oct 25 17:16:51 rivoplus volumio[3110]: info: CorePlayQueue::getQueue Oct 25 17:17:01 rivoplus go-librespot[12097]: time="2025-10-25T17:17:01+03:00" level=trace msg="sent dealer ping" Oct 25 17:17:01 rivoplus go-librespot[12097]: time="2025-10-25T17:17:01+03:00" level=trace msg="received dealer pong" Oct 25 17:17:01 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:03 rivoplus volumio[3110]: info: Executing endpoint metavolumio Oct 25 17:17:03 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 25 17:17:03 rivoplus volumio[3110]: info: Executing endpoint metavolumio Oct 25 17:17:03 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 25 17:17:03 rivoplus volumio[3110]: info: Executing endpoint metavolumio Oct 25 17:17:03 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 25 17:17:04 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:04 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:04 rivoplus volumio[3110]: info: Currently active: spop Oct 25 17:17:04 rivoplus volumio[3110]: info: Stopping currently active service Oct 25 17:17:04 rivoplus volumio[3110]: info: CoreCommandRouter::volumioStop Oct 25 17:17:04 rivoplus volumio[3110]: info: CoreStateMachine::stop Oct 25 17:17:04 rivoplus volumio[3110]: info: CoreStateMachine::serviceStop Oct 25 17:17:04 rivoplus volumio[3110]: info: CoreCommandRouter::serviceStop Oct 25 17:17:04 rivoplus volumio[3110]: info: Spotify Stop Oct 25 17:17:04 rivoplus volumio[3110]: SPOTIFY: SPOTIFY STOP Oct 25 17:17:04 rivoplus volumio[3110]: SPOTIFY: {"status":"pause","title":"I Robot","artist":"The Alan Parsons Project","album":"I Robot","albumart":"https://i.scdn.co/image/ab67616d00001e02a20cc321ff5017259984266b","uri":"spotify:track:2QSuqxALyh7JFoQEBxyo0H","trackType":"spotify","codec":"ogg","seek":0,"duration":360,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":100,"dbVolume":null,"mute":false,"disableVolumeControl":true,"stream":false,"updatedb":false,"volatile":true,"service":"spop"} Oct 25 17:17:04 rivoplus volumio[3110]: info: Sending Spotify command to local API: /player/pause Oct 25 17:17:04 rivoplus volumio[3110]: info: TidalConnect Active Oct 25 17:17:04 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:04 rivoplus volumio[3110]: info: Currently active: spop Oct 25 17:17:04 rivoplus volumio[3110]: info: Setting Volatile state to tidalconnect Oct 25 17:17:04 rivoplus volumio[3110]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 25 17:17:04 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:04 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:04 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 17:17:04 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:04 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:04 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:04 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:04 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:04 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:04 rivoplus go-librespot[12097]: time="2025-10-25T17:17:04+03:00" level=debug msg="pause track at 0ms" Oct 25 17:17:05 rivoplus go-librespot[12097]: time="2025-10-25T17:17:05+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 25 17:17:05 rivoplus go-librespot[12097]: time="2025-10-25T17:17:05+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 25 17:17:05 rivoplus go-librespot[12097]: time="2025-10-25T17:17:05+03:00" level=trace msg="emitting websocket event: paused" Oct 25 17:17:05 rivoplus volumio[3110]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:album:2vtMi0d0613jhp85klO9eb","uri":"spotify:track:1OdDILKk5pxLektkU9XGKZ","play_origin":""}} Oct 25 17:17:05 rivoplus volumio[3110]: info: Spotify is playing in volatile mode Oct 25 17:17:05 rivoplus volumio[3110]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 25 17:17:05 rivoplus volumio[3110]: SPOTIFY: UNSET VOLATILE Oct 25 17:17:05 rivoplus volumio[3110]: SPOTIFY: {"status":"pause","title":"Egyptian Danza","artist":"Al Di Meola","album":"Casino","albumart":"https://resources.tidal.com/images/c6b8a680/6fc7/4a5f/98cc/757ee2fcab18/1280x1280.jpg","uri":"","trackType":"tidal","codec":"flac","seek":0,"duration":356,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":false,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"mute":false,"disableVolumeControl":true,"stream":false,"updatedb":false,"volatile":true,"service":"tidalconnect"} Oct 25 17:17:05 rivoplus volumio[3110]: info: Setting Spotify stop after unset volatile call Oct 25 17:17:05 rivoplus volumio[3110]: SPOTIFY: PUSH STATE SPOTIFY Oct 25 17:17:05 rivoplus volumio[3110]: SPOTIFY: {"status":"pause","service":"spop","title":"I Robot","artist":"The Alan Parsons Project","album":"I Robot","albumart":"https://i.scdn.co/image/ab67616d00001e02a20cc321ff5017259984266b","uri":"spotify:track:2QSuqxALyh7JFoQEBxyo0H","trackType":"spotify","seek":0,"duration":360,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 25 17:17:05 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:05 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:05 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 17:17:05 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:05 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:05 rivoplus volumio[3110]: info: Spotify Stop Oct 25 17:17:05 rivoplus volumio[3110]: SPOTIFY: SPOTIFY STOP Oct 25 17:17:05 rivoplus volumio[3110]: SPOTIFY: {"status":"pause","title":"I Robot","artist":"The Alan Parsons Project","album":"I Robot","albumart":"https://i.scdn.co/image/ab67616d00001e02a20cc321ff5017259984266b","uri":"spotify:track:2QSuqxALyh7JFoQEBxyo0H","trackType":"spotify","codec":"ogg","seek":0,"duration":360,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":100,"dbVolume":null,"mute":false,"disableVolumeControl":true,"stream":false,"updatedb":false,"volatile":true,"service":"spop"} Oct 25 17:17:06 rivoplus vtcs[3548]: [2025-10-25 17:17:06.681] [tisoc] [warning] [PlaybackControllerImpl.cpp:520] Illegal state:1 Oct 25 17:17:06 rivoplus vtcs[3548]: [2025-10-25 17:17:06.681] [tisoc] [warning] [PlaybackControllerImpl.cpp:213] Ignore play request because playback state is not STARTED. state_=2, playstate_=1, player_state_=0 Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:06 rivoplus volumio[3110]: info: Pushing metadata Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:06 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:06 rivoplus volumio[3110]: info: Signalling Playback active due to playback status change Oct 25 17:17:06 rivoplus volumio[3110]: info: MCU Signalled Playback Active Oct 25 17:17:07 rivoplus volumio[3110]: verbose: New Socket.io Connection to 192.168.50.86 from 192.168.50.231 UA: Mozilla/5.0 (Linux; Android 15; SM-S911B Build/AP3A.240905.015.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/141.0.7390.97 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Oct 25 17:17:07 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 25 17:17:07 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetVisibleSources Oct 25 17:17:07 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 25 17:17:07 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:07 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 25 17:17:07 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 25 17:17:07 rivoplus volumio[3110]: info: Received Get System Info Oct 25 17:17:07 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 25 17:17:07 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 25 17:17:07 rivoplus volumio[3110]: info: Discovery: Getting this device information Oct 25 17:17:07 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:07 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 25 17:17:07 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:07 rivoplus volumio[3110]: info: Listing playlists Oct 25 17:17:07 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 25 17:17:08 rivoplus vtcs[3548]: [close:85] Entering Oct 25 17:17:08 rivoplus vtcs[3548]: [close:100] Exiting Oct 25 17:17:08 rivoplus volumio[3110]: info: Pushing metadata Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:08 rivoplus volumio[3110]: info: Signalling Playback active due to playback status change Oct 25 17:17:08 rivoplus volumio[3110]: info: Signalling Playback active due to playback status change Oct 25 17:17:08 rivoplus volumio[3110]: info: Signalling Playback active due to playback status change Oct 25 17:17:08 rivoplus volumio[3110]: info: MCU Signalled Playback Inactive Oct 25 17:17:08 rivoplus volumio[3110]: info: MCU Signalled Playback Active Oct 25 17:17:08 rivoplus vtcs[3548]: [close:85] Entering Oct 25 17:17:08 rivoplus vtcs[3548]: [close:100] Exiting Oct 25 17:17:08 rivoplus vtcs[3548]: [open:50] Opening with sample rate: 192000, type: 3 Oct 25 17:17:08 rivoplus vtcs[3548]: [start:106] Entering Oct 25 17:17:08 rivoplus vtcs[3548]: [start:113] Reopening PCM device... Oct 25 17:17:08 rivoplus vtcs[3548]: [reopen:182] ALSA error: Device or resource busy Oct 25 17:17:08 rivoplus vtcs[3548]: [start:114] Error: 3 Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:08 rivoplus volumio[3110]: info: Signalling Playback active due to playback status change Oct 25 17:17:08 rivoplus volumio[3110]: info: Signalling Playback active due to playback status change Oct 25 17:17:08 rivoplus volumio[3110]: info: Executing endpoint metavolumio Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 25 17:17:08 rivoplus volumio[3110]: info: Executing endpoint metavolumio Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 25 17:17:08 rivoplus volumio[3110]: info: Executing endpoint metavolumio Oct 25 17:17:08 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 25 17:17:08 rivoplus vtcs[3548]: [2025-10-25 17:17:08.973] [tisoc] [warning] [flac_decoder.cpp:302] FLACDecoder::error_callback FLAC__STREAM_DECODER_ERROR_STATUS_LOST_SYNC Oct 25 17:17:16 rivoplus vtcs[3548]: [close:85] Entering Oct 25 17:17:16 rivoplus vtcs[3548]: [close:100] Exiting Oct 25 17:17:16 rivoplus volumio[3110]: info: Pushing metadata Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:16 rivoplus volumio[3110]: info: Signalling Playback active due to playback status change Oct 25 17:17:16 rivoplus volumio[3110]: info: Signalling Playback active due to playback status change Oct 25 17:17:16 rivoplus volumio[3110]: info: Pushing metadata Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:16 rivoplus vtcs[3548]: [close:85] Entering Oct 25 17:17:16 rivoplus vtcs[3548]: [close:100] Exiting Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:16 rivoplus volumio[3110]: info: Signalling Playback active due to playback status change Oct 25 17:17:16 rivoplus volumio[3110]: info: Signalling Playback active due to playback status change Oct 25 17:17:16 rivoplus volumio[3110]: info: Signalling Playback active due to playback status change Oct 25 17:17:16 rivoplus volumio[3110]: info: Signalling Playback active due to playback status change Oct 25 17:17:16 rivoplus volumio[3110]: info: MCU Signalled Playback Inactive Oct 25 17:17:16 rivoplus volumio[3110]: info: MCU Signalled Playback Active Oct 25 17:17:16 rivoplus vtcs[3548]: [close:85] Entering Oct 25 17:17:16 rivoplus vtcs[3548]: [close:100] Exiting Oct 25 17:17:16 rivoplus vtcs[3548]: [open:50] Opening with sample rate: 192000, type: 3 Oct 25 17:17:16 rivoplus vtcs[3548]: [start:106] Entering Oct 25 17:17:16 rivoplus vtcs[3548]: [start:113] Reopening PCM device... Oct 25 17:17:16 rivoplus vtcs[3548]: [reopen:182] ALSA error: Device or resource busy Oct 25 17:17:16 rivoplus vtcs[3548]: [start:114] Error: 3 Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:16 rivoplus volumio[3110]: info: Signalling Playback active due to playback status change Oct 25 17:17:16 rivoplus volumio[3110]: verbose: New Socket.io Connection to 192.168.50.86 from 192.168.50.231 UA: Mozilla/5.0 (Linux; Android 15; SM-S911B Build/AP3A.240905.015.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/141.0.7390.97 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetVisibleSources Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 25 17:17:16 rivoplus volumio[3110]: info: Received Get System Info Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 25 17:17:16 rivoplus volumio[3110]: info: Discovery: Getting this device information Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:16 rivoplus volumio[3110]: info: Listing playlists Oct 25 17:17:16 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 25 17:17:17 rivoplus vtcs[3548]: [close:85] Entering Oct 25 17:17:17 rivoplus vtcs[3548]: [close:100] Exiting Oct 25 17:17:17 rivoplus volumio[3110]: info: Pushing metadata Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:17 rivoplus volumio[3110]: info: Signalling Playback active due to playback status change Oct 25 17:17:17 rivoplus volumio[3110]: info: Signalling Playback active due to playback status change Oct 25 17:17:17 rivoplus volumio[3110]: info: MCU Signalled Playback Inactive Oct 25 17:17:17 rivoplus vtcs[3548]: [close:85] Entering Oct 25 17:17:17 rivoplus vtcs[3548]: [close:100] Exiting Oct 25 17:17:17 rivoplus volumio[3110]: info: Pushing metadata Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:17 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:18 rivoplus vtcs[3548]: [close:85] Entering Oct 25 17:17:18 rivoplus vtcs[3548]: [close:100] Exiting Oct 25 17:17:18 rivoplus vtcs[3548]: [open:50] Opening with sample rate: 192000, type: 3 Oct 25 17:17:18 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:18 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:18 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:18 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:19 rivoplus vtcs[3548]: [start:106] Entering Oct 25 17:17:19 rivoplus vtcs[3548]: [start:113] Reopening PCM device... Oct 25 17:17:19 rivoplus vtcs[3548]: [reopen:182] ALSA error: Device or resource busy Oct 25 17:17:19 rivoplus vtcs[3548]: [start:114] Error: 3 Oct 25 17:17:19 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:19 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:19 rivoplus volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 17:17:19 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:19 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:19 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:19 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:19 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:19 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:19 rivoplus volumio[3110]: info: CoreCommandRouter::servicePushState Oct 25 17:17:19 rivoplus volumio[3110]: info: CoreStateMachine::pushState Oct 25 17:17:19 rivoplus volumio[3110]: info: CoreCommandRouter::volumioPushState Oct 25 17:17:19 rivoplus volumio[3110]: info: CoreCommandRouter::volumioGetState Oct 25 17:17:19 rivoplus volumio[3110]: info: Signalling Playback active due to playback status change Oct 25 17:17:19 rivoplus volumio[3110]: info: Signalling Playback active due to playback status change Oct 25 17:17:19 rivoplus volumio[3110]: info: Signalling Playback active due to playback status change Oct 25 17:17:19 rivoplus volumio[3110]: info: MCU Signalled Playback Active Oct 25 17:17:31 rivoplus go-librespot[12097]: time="2025-10-25T17:17:31+03:00" level=trace msg="received accesspoint ping" Oct 25 17:17:31 rivoplus go-librespot[12097]: time="2025-10-25T17:17:31+03:00" level=trace msg="received accesspoint pong ack" Oct 25 17:17:31 rivoplus go-librespot[12097]: time="2025-10-25T17:17:31+03:00" level=trace msg="sent dealer ping" Oct 25 17:17:31 rivoplus go-librespot[12097]: time="2025-10-25T17:17:31+03:00" level=trace msg="received dealer pong" Oct 25 17:17:45 rivoplus volumio[3110]: info: CoreCommandRouter::volumioRemoveQueueItem Oct 25 17:17:45 rivoplus volumio[3110]: info: CoreStateMachine::removeQueueItem Oct 25 17:17:45 rivoplus volumio[3110]: info: CoreStateMachine::stop Oct 25 17:17:45 rivoplus volumio[3110]: info: CoreStateMachine::serviceStop Oct 25 17:17:45 rivoplus volumio[3110]: info: CoreCommandRouter::serviceStop Oct 25 17:17:45 rivoplus volumio[3110]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 25 17:17:45 rivoplus vtcs[3548]: [close:85] Entering Oct 25 17:17:45 rivoplus vtcs[3548]: [close:100] Exiting Oct 25 17:17:45 rivoplus volumio[3110]: TypeError: Cannot read property 'then' of undefined Oct 25 17:17:45 rivoplus volumio[3110]: at CoreStateMachine.removeQueueItem (/volumio/app/statemachine.js:1370:7) Oct 25 17:17:45 rivoplus volumio[3110]: at CoreCommandRouter.volumioRemoveQueueItem (/volumio/app/index.js:121:28) Oct 25 17:17:45 rivoplus volumio[3110]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:173:33) Oct 25 17:17:45 rivoplus volumio[3110]: at Socket.emit (events.js:400:28) Oct 25 17:17:45 rivoplus volumio[3110]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Oct 25 17:17:45 rivoplus volumio[3110]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Oct 25 17:17:45 rivoplus volumio[3110]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 25 17:17:45 rivoplus vtcs[3548]: [2025-10-25 17:17:45] [info] asio async_shutdown error: asio.misc:2 (End of file) Oct 25 17:17:46 rivoplus sudo[970]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-10-25 17:16 Oct 25 17:17:46 rivoplus sudo[970]: 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="669bb6cc406bb77b11c5184fedb8a4dfd19ba4ec" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivoplus" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 11:23:19 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo" VOLUMIO_HASH="ca35d8983c8e34dfa9cca80071cf9105"