May 24 18:43:08 localhost go-librespot[32267]: time="2026-05-24T18:43:08-04:00" level=trace msg="received accesspoint ping" May 24 18:43:08 localhost go-librespot[32267]: time="2026-05-24T18:43:08-04:00" level=trace msg="received accesspoint pong ack" May 24 18:43:09 localhost go-librespot[32267]: time="2026-05-24T18:43:08-04:00" level=trace msg="sent dealer ping" May 24 18:43:09 localhost go-librespot[32267]: time="2026-05-24T18:43:09-04:00" level=trace msg="received dealer pong" May 24 18:43:12 localhost go-librespot[32267]: time="2026-05-24T18:43:12-04:00" level=debug msg="fetched chunk 19/19, size: 481536" uri="spotify:track:3iIF4QP6Zl6bQb7GW9fLEC" May 24 18:43:31 localhost volumio[1218]: info: CorePlayQueue::getTrack 24 May 24 18:43:31 localhost volumio[1218]: info: CorePlayQueue::getTrack 25 May 24 18:43:31 localhost volumio[1218]: info: Prefetching next song May 24 18:43:31 localhost volumio[1218]: info: [1779662611467] ControllerSpotify::prefetch May 24 18:43:31 localhost volumio[1218]: info: Sending Spotify command with payload to local API: /player/add_to_queue May 24 18:43:31 localhost go-librespot[32267]: time="2026-05-24T18:43:31-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 24 18:43:31 localhost go-librespot[32267]: time="2026-05-24T18:43:31-04:00" level=trace msg="prefetch as soon as possible" May 24 18:43:31 localhost go-librespot[32267]: time="2026-05-24T18:43:31-04:00" level=debug msg="prefetching next track" uri="spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO" May 24 18:43:31 localhost go-librespot[32267]: time="2026-05-24T18:43:31-04:00" level=debug msg="selected format OGG_VORBIS_320 (4a9fe5952df4c91712f7facc2b421c283dfeee04)" uri="spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO" May 24 18:43:31 localhost go-librespot[32267]: time="2026-05-24T18:43:31-04:00" level=debug msg="requested aes key for file 4a9fe5952df4c91712f7facc2b421c283dfeee04, gid: 2l2dLHxk5ZZ0uiwhvRsUfO" May 24 18:43:31 localhost go-librespot[32267]: time="2026-05-24T18:43:31-04:00" level=trace msg="found 2 cdn urls" uri="spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO" May 24 18:43:32 localhost go-librespot[32267]: time="2026-05-24T18:43:32-04:00" level=debug msg="fetched first chunk of 9, total size is 4253655 bytes" uri="spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO" May 24 18:43:32 localhost go-librespot[32267]: time="2026-05-24T18:43:32-04:00" level=info msg="prefetched track \"DREAMS COME TRUE\" (duration: 111000ms)" uri="spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO" May 24 18:43:32 localhost go-librespot[32267]: time="2026-05-24T18:43:32-04:00" level=debug msg="fetched chunk 2/8, size: 524288" uri="spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO" May 24 18:43:32 localhost go-librespot[32267]: time="2026-05-24T18:43:32-04:00" level=debug msg="fetched chunk 3/8, size: 524288" uri="spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO" May 24 18:43:32 localhost go-librespot[32267]: time="2026-05-24T18:43:32-04:00" level=debug msg="fetched chunk 1/8, size: 524288" uri="spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO" May 24 18:43:35 localhost volumio[1218]: info: CoreStateMachine::startPlaybackTimer May 24 18:43:35 localhost volumio[1218]: info: CorePlayQueue::getTrack 25 May 24 18:43:36 localhost volumio[1218]: info: CoreStateMachine::pushState May 24 18:43:36 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 24 18:43:36 localhost volumio[1218]: info: CoreCommandRouter::volumioPushState May 24 18:43:36 localhost volumio[1218]: info: MRS: Pushing multiroomSync output update for this device May 24 18:43:36 localhost volumio[1218]: info: MRS: Pushing multiroomSync output May 24 18:43:36 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:43:36 localhost volumio[1218]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 24 18:43:39 localhost go-librespot[32267]: time="2026-05-24T18:43:39-04:00" level=trace msg="sent dealer ping" May 24 18:43:39 localhost go-librespot[32267]: time="2026-05-24T18:43:39-04:00" level=trace msg="received dealer pong" May 24 18:44:01 localhost go-librespot[32267]: time="2026-05-24T18:44:01-04:00" level=trace msg="emitting websocket event: not_playing" May 24 18:44:01 localhost volumio[1218]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:track:0S38Oso3I9vpDXcTb7kYt9","uri":"spotify:track:3iIF4QP6Zl6bQb7GW9fLEC","play_origin":"go-librespot"}} May 24 18:44:01 localhost volumio[1218]: error: Failed to decode event: not_playing May 24 18:44:01 localhost go-librespot[32267]: time="2026-05-24T18:44:01-04:00" level=debug msg="loading track (paused: false, position: 38ms)" uri="spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO" May 24 18:44:01 localhost go-librespot[32267]: time="2026-05-24T18:44:01-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 24 18:44:01 localhost go-librespot[32267]: time="2026-05-24T18:44:01-04:00" level=trace msg="emitting websocket event: will_play" May 24 18:44:01 localhost go-librespot[32267]: time="2026-05-24T18:44:01-04:00" level=info msg="loaded track \"DREAMS COME TRUE\" (paused: false, position: 38ms, duration: 111000ms, prefetched: true)" uri="spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO" May 24 18:44:01 localhost volumio[1218]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0S38Oso3I9vpDXcTb7kYt9","uri":"spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO","play_origin":"go-librespot"}} May 24 18:44:01 localhost go-librespot[32267]: time="2026-05-24T18:44:01-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 24 18:44:01 localhost go-librespot[32267]: time="2026-05-24T18:44:01-04:00" level=trace msg="scheduling prefetch in 81s" May 24 18:44:01 localhost go-librespot[32267]: time="2026-05-24T18:44:01-04:00" level=trace msg="emitting websocket event: metadata" May 24 18:44:01 localhost volumio[1218]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO","name":"DREAMS COME TRUE","artist_names":["excape."],"album_name":"excapecore.","album_cover_url":"https://i.scdn.co/image/ab67616d00001e028579d8bbb437414acc271b74","position":38,"duration":111000,"release_date":"year:2026 month:3 day:3","track_number":1,"disc_number":1}} May 24 18:44:02 localhost go-librespot[32267]: time="2026-05-24T18:44:02-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 24 18:44:02 localhost go-librespot[32267]: time="2026-05-24T18:44:02-04:00" level=trace msg="emitting websocket event: playing" May 24 18:44:02 localhost volumio[1218]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:0S38Oso3I9vpDXcTb7kYt9","uri":"spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO","resume":false,"play_origin":"go-librespot"}} May 24 18:44:02 localhost volumio[1218]: SPOTIFY: PUSH STATE SPOTIFY May 24 18:44:02 localhost volumio[1218]: SPOTIFY: {"status":"play","service":"spop","title":"DREAMS COME TRUE","artist":"excape.","album":"excapecore.","albumart":"https://i.scdn.co/image/ab67616d00001e028579d8bbb437414acc271b74","uri":"spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO","trackType":"spotify","seek":1038,"duration":111,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} May 24 18:44:02 localhost volumio[1218]: info: CoreCommandRouter::servicePushState May 24 18:44:02 localhost volumio[1218]: info: CoreStateMachine::pushState May 24 18:44:02 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 24 18:44:02 localhost volumio[1218]: info: CoreCommandRouter::volumioPushState May 24 18:44:02 localhost volumio[1218]: info: MRS: Pushing multiroomSync output update for this device May 24 18:44:02 localhost volumio[1218]: info: MRS: Pushing multiroomSync output May 24 18:44:02 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:02 localhost volumio[1218]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 24 18:44:02 localhost volumio[1218]: SPOTIFY: PUSH STATE SPOTIFY May 24 18:44:02 localhost volumio[1218]: SPOTIFY: {"status":"play","service":"spop","title":"DREAMS COME TRUE","artist":"excape.","album":"excapecore.","albumart":"https://i.scdn.co/image/ab67616d00001e028579d8bbb437414acc271b74","uri":"spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO","trackType":"spotify","seek":1038,"duration":111,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} May 24 18:44:02 localhost volumio[1218]: info: CoreCommandRouter::servicePushState May 24 18:44:02 localhost volumio[1218]: info: CoreStateMachine::pushState May 24 18:44:02 localhost volumio[1218]: info: CoreCommandRouter::volumioPushState May 24 18:44:02 localhost volumio[1218]: info: MRS: Pushing multiroomSync output update for this device May 24 18:44:02 localhost volumio[1218]: info: MRS: Pushing multiroomSync output May 24 18:44:02 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:02 localhost volumio[1218]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 24 18:44:09 localhost go-librespot[32267]: time="2026-05-24T18:44:09-04:00" level=trace msg="sent dealer ping" May 24 18:44:09 localhost go-librespot[32267]: time="2026-05-24T18:44:09-04:00" level=trace msg="received dealer pong" May 24 18:44:16 localhost go-librespot[32267]: time="2026-05-24T18:44:16-04:00" level=debug msg="fetched chunk 4/8, size: 524288" uri="spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO" May 24 18:44:30 localhost go-librespot[32267]: time="2026-05-24T18:44:30-04:00" level=debug msg="fetched chunk 5/8, size: 524288" uri="spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO" May 24 18:44:38 localhost go-librespot[32267]: time="2026-05-24T18:44:38-04:00" level=trace msg="sent dealer ping" May 24 18:44:39 localhost go-librespot[32267]: time="2026-05-24T18:44:39-04:00" level=trace msg="received dealer pong" May 24 18:44:43 localhost go-librespot[32267]: time="2026-05-24T18:44:43-04:00" level=debug msg="fetched chunk 6/8, size: 524288" uri="spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO" May 24 18:44:47 localhost kernel: usb 1-1.2: USB disconnect, device number 8 May 24 18:44:47 localhost go-librespot[32267]: ALSA lib ./src/pcm_volumioswitch.c:912:(_snd_pcm_volumioswitch_advance) PCM volumioMultiRoomServer cannot write to target PCM volumioOutput as it has failed its update check. May 24 18:44:47 localhost go-librespot[32267]: ALSA lib pcm.c:8573:(snd_pcm_recover) cannot recovery from underrun, prepare failed: No such device May 24 18:44:47 localhost go-librespot[32267]: time="2026-05-24T18:44:47-04:00" level=error msg="output device failed" error="ALSA error at snd_pcm_recover: No such device" May 24 18:44:47 localhost go-librespot[32267]: time="2026-05-24T18:44:47-04:00" level=trace msg="cleared closed output device" May 24 18:44:47 localhost go-librespot[32267]: time="2026-05-24T18:44:47-04:00" level=trace msg="emitting websocket event: stopped" May 24 18:44:47 localhost volumio[1218]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}} May 24 18:44:47 localhost volumio[1218]: SPOTIFY: PUSH STATE SPOTIFY May 24 18:44:47 localhost volumio[1218]: SPOTIFY: {"status":"stop","service":"spop","title":"DREAMS COME TRUE","artist":"excape.","album":"excapecore.","albumart":"https://i.scdn.co/image/ab67616d00001e028579d8bbb437414acc271b74","uri":"spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO","trackType":"spotify","seek":46038,"duration":111,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} May 24 18:44:47 localhost volumio[1218]: info: CoreCommandRouter::servicePushState May 24 18:44:47 localhost volumio[1218]: info: CoreStateMachine::pushState May 24 18:44:47 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 24 18:44:47 localhost volumio[1218]: info: CoreCommandRouter::volumioPushState May 24 18:44:47 localhost volumio[1218]: info: MRS: Pushing multiroomSync output update for this device May 24 18:44:47 localhost volumio[1218]: info: MRS: Pushing multiroomSync output May 24 18:44:47 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:47 localhost volumio[1218]: info: CorePlayQueue::getTrack 25 May 24 18:44:47 localhost volumio[1218]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"DREAMS COME TRUE","artist":"excape.","album":"excapecore.","albumart":"https://i.scdn.co/image/ab67616d00001e028579d8bbb437414acc271b74","uri":"spotify:track:2l2dLHxk5ZZ0uiwhvRsUfO","trackType":"spotify","seek":46038,"duration":111,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} May 24 18:44:47 localhost volumio[1218]: verbose: CURRENT POSITION 25 May 24 18:44:47 localhost volumio[1218]: info: CoreStateMachine::syncState stateService stop May 24 18:44:47 localhost volumio[1218]: info: CoreStateMachine::syncState currentStatus play May 24 18:44:47 localhost volumio[1218]: info: CoreStateMachine::play index undefined May 24 18:44:47 localhost volumio[1218]: info: CoreStateMachine::setConsumeUpdateService undefined May 24 18:44:47 localhost volumio[1218]: info: CoreStateMachine::pushState May 24 18:44:47 localhost volumio[1218]: info: CoreCommandRouter::volumioPushState May 24 18:44:47 localhost volumio[1218]: info: MRS: Pushing multiroomSync output update for this device May 24 18:44:47 localhost volumio[1218]: info: MRS: Pushing multiroomSync output May 24 18:44:47 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:47 localhost volumio[1218]: info: CorePlayQueue::getTrack 26 May 24 18:44:47 localhost volumio[1218]: info: CoreStateMachine::startPlaybackTimer May 24 18:44:47 localhost volumio[1218]: info: CorePlayQueue::getTrack 26 May 24 18:44:47 localhost volumio[1218]: info: [1779662687436] ControllerSpotify::clearAddPlayTrack May 24 18:44:47 localhost volumio[1218]: info: Sending Spotify command with payload to local API: /player/play May 24 18:44:47 localhost volumio[1218]: info: CoreStateMachine::pushState May 24 18:44:47 localhost volumio[1218]: info: CoreCommandRouter::volumioPushState May 24 18:44:47 localhost volumio[1218]: info: MRS: Pushing multiroomSync output update for this device May 24 18:44:47 localhost volumio[1218]: info: MRS: Pushing multiroomSync output May 24 18:44:47 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:47 localhost volumio[1218]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 24 18:44:47 localhost volumio[1218]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 24 18:44:47 localhost volumio[1218]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 24 18:44:47 localhost volumio[1218]: info: May 24 18:44:47 localhost volumio[1218]: ---------------------------- USB Audio Device Detached May 24 18:44:47 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioDetach May 24 18:44:47 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 24 18:44:47 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: raat , onStop May 24 18:44:47 localhost go-librespot[32267]: time="2026-05-24T18:44:47-04:00" level=debug msg="resolved context of track" uri="spotify:track:7nLTzZYZszjRTipe4QmvQO" May 24 18:44:47 localhost go-librespot[32267]: time="2026-05-24T18:44:47-04:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7nLTzZYZszjRTipe4QmvQO" May 24 18:44:47 localhost go-librespot[32267]: time="2026-05-24T18:44:47-04:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7nLTzZYZszjRTipe4QmvQO" May 24 18:44:47 localhost kernel: usb 1-1.2: new high-speed USB device number 9 using xhci_hcd May 24 18:44:47 localhost go-librespot[32267]: time="2026-05-24T18:44:47-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 24 18:44:47 localhost go-librespot[32267]: time="2026-05-24T18:44:47-04:00" level=trace msg="emitting websocket event: will_play" May 24 18:44:47 localhost volumio[1218]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7nLTzZYZszjRTipe4QmvQO","uri":"spotify:track:7nLTzZYZszjRTipe4QmvQO","play_origin":"go-librespot"}} May 24 18:44:47 localhost go-librespot[32267]: time="2026-05-24T18:44:47-04:00" level=debug msg="selected format OGG_VORBIS_320 (1afa26098fec16e3f01735329862d053ffd0856e)" uri="spotify:track:7nLTzZYZszjRTipe4QmvQO" May 24 18:44:47 localhost go-librespot[32267]: time="2026-05-24T18:44:47-04:00" level=debug msg="requested aes key for file 1afa26098fec16e3f01735329862d053ffd0856e, gid: 7nLTzZYZszjRTipe4QmvQO" May 24 18:44:47 localhost go-librespot[32267]: time="2026-05-24T18:44:47-04:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7nLTzZYZszjRTipe4QmvQO" May 24 18:44:47 localhost kernel: usb 1-1.2: device descriptor read/64, error -71 May 24 18:44:48 localhost go-librespot[32267]: time="2026-05-24T18:44:48-04:00" level=debug msg="fetched first chunk of 5, total size is 2353468 bytes" uri="spotify:track:7nLTzZYZszjRTipe4QmvQO" May 24 18:44:48 localhost go-librespot[32267]: time="2026-05-24T18:44:48-04:00" level=debug msg="created new output device" May 24 18:44:48 localhost go-librespot[32267]: ALSA lib confmisc.c:165:(snd_config_get_card) Cannot get card index for D50s May 24 18:44:48 localhost go-librespot[32267]: ALSA lib ./src/pcm_volumioswitch.c:143:(_snd_pcm_volumioswitch_open_target_pcm) PCM Volumio ALSA Switch Plugin failed to open the switcher target pcm volumioLocalPlayback May 24 18:44:48 localhost go-librespot[32267]: time="2026-05-24T18:44:48-04:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:7nLTzZYZszjRTipe4QmvQO: ALSA error at snd_pcm_open: No such device" May 24 18:44:48 localhost volumio[1218]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 24 18:44:48 localhost go-librespot[32267]: time="2026-05-24T18:44:48-04:00" level=debug msg="fetched chunk 2/4, size: 524288" uri="spotify:track:7nLTzZYZszjRTipe4QmvQO" May 24 18:44:48 localhost go-librespot[32267]: time="2026-05-24T18:44:48-04:00" level=debug msg="fetched chunk 3/4, size: 524288" uri="spotify:track:7nLTzZYZszjRTipe4QmvQO" May 24 18:44:48 localhost go-librespot[32267]: time="2026-05-24T18:44:48-04:00" level=debug msg="fetched chunk 1/4, size: 524288" uri="spotify:track:7nLTzZYZszjRTipe4QmvQO" May 24 18:44:48 localhost kernel: usb 1-1.2: device descriptor read/64, error -71 May 24 18:44:48 localhost kernel: usb 1-1.2: new high-speed USB device number 10 using xhci_hcd May 24 18:44:49 localhost kernel: usb 1-1.2: device descriptor read/64, error -71 May 24 18:44:49 localhost kernel: usb 1-1.2: New USB device found, idVendor=152a, idProduct=8750, bcdDevice= 1.03 May 24 18:44:49 localhost kernel: usb 1-1.2: New USB device strings: Mfr=1, Product=3, SerialNumber=0 May 24 18:44:49 localhost kernel: usb 1-1.2: Product: D50s May 24 18:44:49 localhost kernel: usb 1-1.2: Manufacturer: Topping May 24 18:44:49 localhost kernel: usb 1-1.2: USB disconnect, device number 10 May 24 18:44:49 localhost (udev-worker)[911]: controlC5: /usr/lib/udev/rules.d/78-sound-card.rules:5 Failed to write ATTR{/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.2/1-1.2:1.0/sound/card5/controlC5/../uevent}, ignoring: No such file or directory May 24 18:44:49 localhost volumio[1218]: info: May 24 18:44:49 localhost volumio[1218]: ---------------------------- USB Audio Device Attached May 24 18:44:49 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioAttach May 24 18:44:49 localhost volumio[1218]: error: API:pushError: TypeError: Cannot read properties of null (reading 'name') May 24 18:44:49 localhost volumio[1218]: info: May 24 18:44:49 localhost volumio[1218]: ---------------------------- USB Audio Device Detached May 24 18:44:49 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioDetach May 24 18:44:49 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 24 18:44:49 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: raat , onStop May 24 18:44:49 localhost kernel: usb 1-1.2: new high-speed USB device number 11 using xhci_hcd May 24 18:44:49 localhost kernel: usb 1-1.2: New USB device found, idVendor=152a, idProduct=8750, bcdDevice= 1.03 May 24 18:44:49 localhost kernel: usb 1-1.2: New USB device strings: Mfr=1, Product=3, SerialNumber=0 May 24 18:44:49 localhost kernel: usb 1-1.2: Product: D50s May 24 18:44:49 localhost kernel: usb 1-1.2: Manufacturer: Topping May 24 18:44:49 localhost volumio[1218]: info: May 24 18:44:49 localhost volumio[1218]: ---------------------------- USB Audio Device Attached May 24 18:44:49 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioAttach May 24 18:44:49 localhost volumio[1218]: info: CoreCommandRouter::Close All Modals sent May 24 18:44:49 localhost volumio[1218]: info: Preparing to save Alsa Options, stopping services first May 24 18:44:49 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:49 localhost volumio[1218]: info: CoreCommandRouter::volumioPause May 24 18:44:49 localhost volumio[1218]: info: CoreStateMachine::pause May 24 18:44:49 localhost volumio[1218]: info: Saving Audio Output to: {"disallowPush":true,"output_device":{"value":"5","label":"D50s","alsacard":"D50s"},"i2s":false} May 24 18:44:49 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 24 18:44:49 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 24 18:44:49 localhost volumio[1218]: info: Setting mixer D50s for card D50s May 24 18:44:49 localhost volumio[1218]: info: QobuzConnect: setDeactiveState invoked May 24 18:44:49 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:49 localhost vtcs[32171]: [2026-05-24 18:44:49.920] [tisoc] [error] [SpkconServer.cpp:378] recv error. socket disconnected May 24 18:44:49 localhost vtcs[32171]: [2026-05-24 18:44:49.921] [tisoc] [warning] [SessionManagerImpl.cpp:240] Illegal State: IDLE May 24 18:44:49 localhost sudo[951]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 24 18:44:49 localhost sudo[951]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:49 localhost volumio[1218]: info: CoreCommandRouter::volumioUpdateVolumeSettings May 24 18:44:49 localhost volumio[1218]: info: Updating Volume Controller Parameters: Device: 5 Name: D50s Mixer: D50s Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 May 24 18:44:49 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume May 24 18:44:49 localhost volumio[1218]: info: Disabling external Volume Control May 24 18:44:49 localhost volumio[1218]: info: CoreCommandRouter::getUIConfigOnPlugin May 24 18:44:49 localhost systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... May 24 18:44:49 localhost volumio[1218]: info: Preparing to generate the ALSA configuration file May 24 18:44:49 localhost systemd[1]: vtcs.service: Deactivated successfully. May 24 18:44:49 localhost systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. May 24 18:44:49 localhost sudo[951]: pam_unix(sudo:session): session closed for user root May 24 18:44:50 localhost sudo[962]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 24 18:44:50 localhost sudo[962]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:50 localhost volumio[1218]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf May 24 18:44:50 localhost volumio[1218]: info: Reading ALSA contributions from plugins. May 24 18:44:50 localhost sudo[969]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service May 24 18:44:50 localhost sudo[969]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:50 localhost sudo[962]: pam_unix(sudo:session): session closed for user root May 24 18:44:50 localhost sudo[969]: pam_unix(sudo:session): session closed for user root May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 24 18:44:50 localhost sudo[976]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service May 24 18:44:50 localhost sudo[976]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus May 24 18:44:50 localhost systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... May 24 18:44:50 localhost qobuz-connect[32213]: 20260524 18:44:50.122 [32213.32213] INFO SampleApp: Stopping Local configuration server May 24 18:44:50 localhost volumio[1218]: info: VolumeController:: Volume=100 Mute =false May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:50 localhost volumio[1218]: info: CoreStateMachine::pushState May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::volumioPushState May 24 18:44:50 localhost volumio[1218]: info: MRS: Pushing multiroomSync output update for this device May 24 18:44:50 localhost volumio[1218]: info: MRS: Pushing multiroomSync output May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:50 localhost volumio[1218]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 24 18:44:50 localhost volumio[1218]: info: Asound.conf file unchanged, so no further update is needed May 24 18:44:50 localhost volumio[1218]: info: Output device has changed, restarting MPD May 24 18:44:50 localhost volumio[1218]: info: Output device has changed, restarting Shairport Sync May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 24 18:44:50 localhost sudo[987]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 24 18:44:50 localhost sudo[987]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:50 localhost sudo[987]: pam_unix(sudo:session): session closed for user root May 24 18:44:50 localhost sudo[990]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 24 18:44:50 localhost sudo[990]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:50 localhost volumio[1218]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 24 18:44:50 localhost volumio[1218]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: QobuzConnect: setDeactiveState invoked May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:50 localhost systemd[1]: Stopping mpd.service - Music Player Daemon... May 24 18:44:50 localhost sudo[1003]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 24 18:44:50 localhost sudo[1003]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:50 localhost sudo[1005]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 24 18:44:50 localhost sudo[1005]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:50 localhost systemd[1]: mpd.service: Deactivated successfully. May 24 18:44:50 localhost systemd[1]: Stopped mpd.service - Music Player Daemon. May 24 18:44:50 localhost systemd[1]: mpd.service: Consumed 1.472s CPU time. May 24 18:44:50 localhost systemd[1]: mpd.socket: Deactivated successfully. May 24 18:44:50 localhost systemd[1]: Closed mpd.socket - Music Player Daemon Socket. May 24 18:44:50 localhost systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... May 24 18:44:50 localhost volumio[1218]: info: MPD Permissions set May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:50 localhost sudo[1013]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service May 24 18:44:50 localhost sudo[1013]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:50 localhost volumio[1218]: info: Starting Shairport Sync May 24 18:44:50 localhost systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. May 24 18:44:50 localhost systemd[1]: Starting mpd.service - Music Player Daemon... May 24 18:44:50 localhost sudo[1024]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 24 18:44:50 localhost sudo[1024]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:50 localhost sudo[1013]: pam_unix(sudo:session): session closed for user root May 24 18:44:50 localhost sudo[1003]: pam_unix(sudo:session): session closed for user root May 24 18:44:50 localhost sudo[1026]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service May 24 18:44:50 localhost sudo[1026]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:50 localhost sudo[1005]: pam_unix(sudo:session): session closed for user root May 24 18:44:50 localhost systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... May 24 18:44:50 localhost systemd[1]: shairport-sync.service: Deactivated successfully. May 24 18:44:50 localhost systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 24 18:44:50 localhost systemd[1]: shairport-sync.service: Consumed 3.460s CPU time. May 24 18:44:50 localhost systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 24 18:44:50 localhost sudo[1024]: pam_unix(sudo:session): session closed for user root May 24 18:44:50 localhost volumio[1218]: info: Shairport-Sync Started May 24 18:44:50 localhost sudo[1023]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 24 18:44:50 localhost sudo[1023]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) May 24 18:44:50 localhost sudo[1023]: pam_unix(sudo:session): session closed for user root May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: raat , restartRaat May 24 18:44:50 localhost qobuz-connect[32213]: 20260524 18:44:50.711 [32213.32213] INFO SampleApp: shat down connection on UNIX socket May 24 18:44:50 localhost volumio[1218]: info: QobuzConnect: Qobuz Connect client [object Object] disconnected May 24 18:44:50 localhost volumio[1218]: info: QobuzConnect: setDeactiveState invoked May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:50 localhost systemd[1]: qobuz-connect.service: Deactivated successfully. May 24 18:44:50 localhost systemd[1]: Stopped qobuz-connect.service - Volumio Qobuz Connect Service. May 24 18:44:50 localhost systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. May 24 18:44:50 localhost sudo[976]: pam_unix(sudo:session): session closed for user root May 24 18:44:50 localhost sudo[1026]: pam_unix(sudo:session): session closed for user root May 24 18:44:50 localhost volumio[1218]: info: Executing endpoint qc_getconfig May 24 18:44:50 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig May 24 18:44:50 localhost qobuz-connect[1050]: 20260524 18:44:50.862 [1050.1050] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket May 24 18:44:50 localhost volumio[1218]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] May 24 18:44:50 localhost volumio[1218]: info: QobuzConnect: QOBUZ Connect daemon connected May 24 18:44:50 localhost qobuz-connect[1050]: 20260524 18:44:50.866 [1050.1050] INFO VolumeManager: [0x1791288]: Setting new playback volume: 75 May 24 18:44:50 localhost qobuz-connect[1050]: 20260524 18:44:50.866 [1050.1050] INFO VolumeManager: [0x1791288]: Setting new mute state: 0 May 24 18:44:50 localhost qobuz-connect[1050]: 20260524 18:44:50.866 [1050.1050] INFO AudioStreamManager: [0x1790fe0]: Setting new audio download buffer size: 1048576 May 24 18:44:50 localhost qobuz-connect[1050]: 20260524 18:44:50.866 [1050.1050] INFO QobuzConnect: [0x1791b50]: Client initialized! May 24 18:44:50 localhost qobuz-connect[1050]: 20260524 18:44:50.866 [1050.1050] INFO SampleApp: Starting Avahi advertising, name: Volumio Jey, service name: _qobuz-connect._tcp May 24 18:44:50 localhost qobuz-connect[1050]: 20260524 18:44:50.882 [1050.1050] INFO LocalConfigManager: [0x1790d08]: Starting Local Configuration server May 24 18:44:50 localhost qobuz-connect[1050]: 20260524 18:44:50.882 [1050.1050] INFO SampleApp: Starting Local configuration server May 24 18:44:50 localhost qobuz-connect[1050]: 20260524 18:44:50.883 [1050.1050] INFO SampleApp: Connected to UNIX socket client 0x177b818 May 24 18:44:51 localhost qobuz-connect[1050]: 20260524 18:44:51.012 [1050.1050] INFO SampleApp: Playback volume changed: 75 May 24 18:44:51 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:51 localhost kernel: usb 1-1.2: USB disconnect, device number 11 May 24 18:44:51 localhost volumio[1218]: info: May 24 18:44:51 localhost volumio[1218]: ---------------------------- USB Audio Device Detached May 24 18:44:51 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioDetach May 24 18:44:51 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 24 18:44:51 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: raat , onStop May 24 18:44:51 localhost mpd[1034]: 2026-05-24T18:44:51 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 24 18:44:51 localhost systemd[1]: Started mpd.service - Music Player Daemon. May 24 18:44:51 localhost sudo[990]: pam_unix(sudo:session): session closed for user root May 24 18:44:51 localhost volumio[1218]: error: updateQueue error: null May 24 18:44:52 localhost kernel: usb 1-1-port2: Cannot enable. Maybe the USB cable is bad? May 24 18:44:52 localhost volumio[1218]: info: TidalConnect service stoped! May 24 18:44:53 localhost kernel: usb 1-1.2: new high-speed USB device number 13 using xhci_hcd May 24 18:44:53 localhost volumio[1218]: info: TidalConnect service stoped! May 24 18:44:53 localhost volumio[1218]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect May 24 18:44:53 localhost volumio[1218]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect May 24 18:44:53 localhost sudo[1100]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service May 24 18:44:53 localhost sudo[1100]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:53 localhost kernel: usb 1-1.2: New USB device found, idVendor=152a, idProduct=8750, bcdDevice= 1.03 May 24 18:44:53 localhost kernel: usb 1-1.2: New USB device strings: Mfr=1, Product=3, SerialNumber=0 May 24 18:44:53 localhost kernel: usb 1-1.2: Product: D50s May 24 18:44:53 localhost kernel: usb 1-1.2: Manufacturer: Topping May 24 18:44:53 localhost systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. May 24 18:44:53 localhost sudo[1100]: pam_unix(sudo:session): session closed for user root May 24 18:44:53 localhost volumio[1218]: info: May 24 18:44:53 localhost volumio[1218]: ---------------------------- USB Audio Device Attached May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioAttach May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::Close All Modals sent May 24 18:44:53 localhost volumio[1218]: info: Preparing to save Alsa Options, stopping services first May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::volumioPause May 24 18:44:53 localhost volumio[1218]: info: CoreStateMachine::pause May 24 18:44:53 localhost volumio[1218]: info: Saving Audio Output to: {"disallowPush":true,"output_device":{"value":"5","label":"D50s","alsacard":"D50s"},"i2s":false} May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 24 18:44:53 localhost volumio[1218]: info: Setting mixer D50s for card D50s May 24 18:44:53 localhost volumio[1218]: info: QobuzConnect: setDeactiveState invoked May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:53 localhost sudo[1124]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 24 18:44:53 localhost sudo[1124]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::volumioUpdateVolumeSettings May 24 18:44:53 localhost volumio[1218]: info: Updating Volume Controller Parameters: Device: 5 Name: D50s Mixer: D50s Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume May 24 18:44:53 localhost volumio[1218]: info: Disabling external Volume Control May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::getUIConfigOnPlugin May 24 18:44:53 localhost systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... May 24 18:44:53 localhost volumio[1218]: info: Preparing to generate the ALSA configuration file May 24 18:44:53 localhost systemd[1]: vtcs.service: Deactivated successfully. May 24 18:44:53 localhost systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. May 24 18:44:53 localhost sudo[1124]: pam_unix(sudo:session): session closed for user root May 24 18:44:53 localhost sudo[1132]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 24 18:44:53 localhost sudo[1132]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:53 localhost volumio[1218]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf May 24 18:44:53 localhost volumio[1218]: info: Reading ALSA contributions from plugins. May 24 18:44:53 localhost sudo[1139]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service May 24 18:44:53 localhost sudo[1139]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:53 localhost volumio[1218]: info: TidalConnect service stoped! May 24 18:44:53 localhost volumio[1218]: info: TidalConnect service stoped! May 24 18:44:53 localhost volumio[1218]: info: Executing endpoint tc_getconfig May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig May 24 18:44:53 localhost volumio[1218]: info: VolumeController:: Volume=100 Mute =false May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:53 localhost volumio[1218]: info: CoreStateMachine::pushState May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::volumioPushState May 24 18:44:53 localhost volumio[1218]: info: MRS: Pushing multiroomSync output update for this device May 24 18:44:53 localhost volumio[1218]: info: MRS: Pushing multiroomSync output May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:53 localhost sudo[1132]: pam_unix(sudo:session): session closed for user root May 24 18:44:53 localhost volumio[1218]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 24 18:44:53 localhost sudo[1139]: pam_unix(sudo:session): session closed for user root May 24 18:44:53 localhost sudo[1147]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service May 24 18:44:53 localhost sudo[1147]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 24 18:44:53 localhost systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... May 24 18:44:53 localhost qobuz-connect[1050]: 20260524 18:44:53.523 [1050.1050] INFO SampleApp: Stopping Local configuration server May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus May 24 18:44:53 localhost volumio[1218]: info: Asound.conf file unchanged, so no further update is needed May 24 18:44:53 localhost volumio[1218]: info: Output device has changed, restarting MPD May 24 18:44:53 localhost volumio[1218]: info: Output device has changed, restarting Shairport Sync May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 24 18:44:53 localhost sudo[1160]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 24 18:44:53 localhost sudo[1160]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:53 localhost sudo[1160]: pam_unix(sudo:session): session closed for user root May 24 18:44:53 localhost sudo[1162]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 24 18:44:53 localhost sudo[1162]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:53 localhost volumio[1218]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 24 18:44:53 localhost volumio[1218]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: QobuzConnect: setDeactiveState invoked May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:53 localhost systemd[1]: Stopping mpd.service - Music Player Daemon... May 24 18:44:53 localhost sudo[1172]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 24 18:44:53 localhost sudo[1172]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:53 localhost systemd[1]: mpd.service: Deactivated successfully. May 24 18:44:53 localhost systemd[1]: Stopped mpd.service - Music Player Daemon. May 24 18:44:53 localhost systemd[1]: mpd.service: Consumed 1.455s CPU time. May 24 18:44:53 localhost sudo[1174]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 24 18:44:53 localhost systemd[1]: mpd.socket: Deactivated successfully. May 24 18:44:53 localhost sudo[1174]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:53 localhost systemd[1]: Closed mpd.socket - Music Player Daemon Socket. May 24 18:44:53 localhost systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... May 24 18:44:53 localhost volumio[1218]: info: MPD Permissions set May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::volumioGetState May 24 18:44:53 localhost volumio[1218]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect May 24 18:44:53 localhost volumio[1218]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:53 localhost sudo[1184]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service May 24 18:44:53 localhost sudo[1184]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 18:44:53 localhost volumio[1218]: info: Starting Shairport Sync May 24 18:44:53 localhost sudo[1192]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service May 24 18:44:53 localhost sudo[1192]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:53 localhost sudo[1194]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 24 18:44:53 localhost systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. May 24 18:44:53 localhost sudo[1194]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:53 localhost systemd[1]: Starting mpd.service - Music Player Daemon... May 24 18:44:53 localhost sudo[1184]: pam_unix(sudo:session): session closed for user root May 24 18:44:53 localhost sudo[1172]: pam_unix(sudo:session): session closed for user root May 24 18:44:53 localhost sudo[1174]: pam_unix(sudo:session): session closed for user root May 24 18:44:53 localhost volumio[1218]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 24 18:44:53 localhost systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... May 24 18:44:53 localhost volumio[1218]: Error: Command failed: /usr/bin/sudo /bin/systemctl stop vtcs.service && sleep 3 May 24 18:44:53 localhost volumio[1218]: Job for vtcs.service canceled. May 24 18:44:53 localhost volumio[1218]: at ChildProcess.exithandler (node:child_process:421:12) May 24 18:44:53 localhost volumio[1218]: at ChildProcess.emit (node:events:514:28) May 24 18:44:53 localhost volumio[1218]: at maybeClose (node:internal/child_process:1105:16) May 24 18:44:53 localhost volumio[1218]: at ChildProcess._handle.onexit (node:internal/child_process:305:5) { May 24 18:44:53 localhost volumio[1218]: code: 1, May 24 18:44:53 localhost volumio[1218]: killed: false, May 24 18:44:53 localhost volumio[1218]: signal: null, May 24 18:44:53 localhost volumio[1218]: cmd: '/usr/bin/sudo /bin/systemctl stop vtcs.service && sleep 3', May 24 18:44:53 localhost volumio[1218]: stdout: '', May 24 18:44:53 localhost volumio[1218]: stderr: 'Job for vtcs.service canceled.\n' May 24 18:44:53 localhost volumio[1218]: } May 24 18:44:53 localhost volumio[1218]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 24 18:44:53 localhost sudo[1198]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service May 24 18:44:53 localhost sudo[1198]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 24 18:44:53 localhost sudo[1197]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 24 18:44:53 localhost sudo[1197]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) May 24 18:44:53 localhost sudo[1197]: pam_unix(sudo:session): session closed for user root May 24 18:44:53 localhost systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. May 24 18:44:53 localhost systemd[1]: shairport-sync.service: Deactivated successfully. May 24 18:44:53 localhost sudo[1192]: pam_unix(sudo:session): session closed for user root May 24 18:44:53 localhost systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 24 18:44:53 localhost systemd[1]: shairport-sync.service: Consumed 1.549s CPU time. May 24 18:44:53 localhost systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 24 18:44:53 localhost sudo[1194]: pam_unix(sudo:session): session closed for user root May 24 18:44:54 localhost sudo[1246]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-05-24 18:43' May 24 18:44:54 localhost sudo[1246]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="dc61260dec5515dafd2b634881860b4c46c919ff" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Mar 6 16:46:58 UTC 2026" VOLUMIO_VERSION="4.103" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="aa741395b8bfc648ff5d04e312f53d2c"