Mar 28 16:10:08 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:08+01:00" level=trace msg="sent dealer ping" Mar 28 16:10:08 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:08+01:00" level=trace msg="received dealer pong" Mar 28 16:10:10 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 15 Mar 28 16:10:10 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:10:10 volumiopi3 volumio[1226]: info: Prefetching next song Mar 28 16:10:10 volumiopi3 volumio[1226]: info: [1774710610193] ControllerSpotify::prefetch Mar 28 16:10:10 volumiopi3 volumio[1226]: info: Sending Spotify command with payload to local API: /player/add_to_queue Mar 28 16:10:10 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:10+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 16:10:10 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:10+01:00" level=trace msg="prefetch as soon as possible" Mar 28 16:10:10 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:10+01:00" level=debug msg="prefetching next track" uri="spotify:track:4d4kYbA548nktAko22mRCp" Mar 28 16:10:10 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:10+01:00" level=debug msg="selected format OGG_VORBIS_320 (37be59bc78f12069499ddad7e3b34afd8adaeb98)" uri="spotify:track:4d4kYbA548nktAko22mRCp" Mar 28 16:10:10 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:10+01:00" level=debug msg="requested aes key for file 37be59bc78f12069499ddad7e3b34afd8adaeb98, gid: 4d4kYbA548nktAko22mRCp" Mar 28 16:10:10 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:10+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4d4kYbA548nktAko22mRCp" Mar 28 16:10:10 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:10+01:00" level=debug msg="fetched first chunk of 30, total size is 15292840 bytes" uri="spotify:track:4d4kYbA548nktAko22mRCp" Mar 28 16:10:10 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:10+01:00" level=info msg="prefetched track \"This Is the Sea - Live\" (duration: 355400ms)" uri="spotify:track:4d4kYbA548nktAko22mRCp" Mar 28 16:10:11 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:11+01:00" level=debug msg="fetched chunk 1/29, size: 524288" uri="spotify:track:4d4kYbA548nktAko22mRCp" Mar 28 16:10:11 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:11+01:00" level=debug msg="fetched chunk 3/29, size: 524288" uri="spotify:track:4d4kYbA548nktAko22mRCp" Mar 28 16:10:11 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:11+01:00" level=debug msg="fetched chunk 2/29, size: 524288" uri="spotify:track:4d4kYbA548nktAko22mRCp" Mar 28 16:10:11 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:11+01:00" level=trace msg="emitting websocket event: not_playing" Mar 28 16:10:11 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:11+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4d4kYbA548nktAko22mRCp" Mar 28 16:10:11 volumiopi3 volumio[1226]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:track:6uPaSEHsa9NQMa94IrdKAg","uri":"spotify:track:5inWNELZUTSyzrfibBtt1m","play_origin":"go-librespot"}} Mar 28 16:10:11 volumiopi3 volumio[1226]: error: Failed to decode event: not_playing Mar 28 16:10:11 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:11+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 16:10:11 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:11+01:00" level=trace msg="emitting websocket event: will_play" Mar 28 16:10:11 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:11+01:00" level=info msg="loaded track \"This Is the Sea - Live\" (paused: false, position: 0ms, duration: 355400ms, prefetched: true)" uri="spotify:track:4d4kYbA548nktAko22mRCp" Mar 28 16:10:11 volumiopi3 volumio[1226]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:6uPaSEHsa9NQMa94IrdKAg","uri":"spotify:track:4d4kYbA548nktAko22mRCp","play_origin":"go-librespot"}} Mar 28 16:10:12 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:12+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 16:10:12 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:12+01:00" level=trace msg="scheduling prefetch in 325s" Mar 28 16:10:12 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:12+01:00" level=trace msg="emitting websocket event: metadata" Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4d4kYbA548nktAko22mRCp","name":"This Is the Sea - Live","artist_names":["The Waterboys"],"album_name":"This Is the Sea (Deluxe Version)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02f74c4e155d96ffed4b759b59","position":0,"duration":355400,"release_date":"year:1985 month:9 day:16","track_number":8,"disc_number":2}} Mar 28 16:10:12 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:12+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 16:10:12 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:12+01:00" level=trace msg="emitting websocket event: playing" Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:6uPaSEHsa9NQMa94IrdKAg","uri":"spotify:track:4d4kYbA548nktAko22mRCp","resume":false,"play_origin":"go-librespot"}} Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: PUSH STATE SPOTIFY Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: {"status":"play","service":"spop","title":"This Is the Sea - Live","artist":"The Waterboys","album":"This Is the Sea (Deluxe Version)","albumart":"https://i.scdn.co/image/ab67616d00001e02f74c4e155d96ffed4b759b59","uri":"spotify:track:4d4kYbA548nktAko22mRCp","trackType":"spotify","seek":0,"duration":355,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CoreCommandRouter::servicePushState Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 15 Mar 28 16:10:12 volumiopi3 volumio[1226]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"This Is the Sea - Live","artist":"The Waterboys","album":"This Is the Sea (Deluxe Version)","albumart":"https://i.scdn.co/image/ab67616d00001e02f74c4e155d96ffed4b759b59","uri":"spotify:track:4d4kYbA548nktAko22mRCp","trackType":"spotify","seek":0,"duration":355,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 28 16:10:12 volumiopi3 volumio[1226]: verbose: CURRENT POSITION 15 Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CoreStateMachine::syncState stateService play Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CoreStateMachine::syncState currentStatus play Mar 28 16:10:12 volumiopi3 volumio[1226]: info: Received an update from plugin. extracting info from payload Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CoreStateMachine::pushState Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 15 Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioPushState Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CoreStateMachine::pushState Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 15 Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioPushState Mar 28 16:10:12 volumiopi3 volumio5-onboarding[2290]: time=2026-03-28T16:10:12.212+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.5:46814 @ 0x2504240" state=STATUS_PLAYING positionMs=271772 volume=77 Mar 28 16:10:12 volumiopi3 volumio5-onboarding[2290]: time=2026-03-28T16:10:12.218+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.5:46814 @ 0x2504240" state=STATUS_PLAYING positionMs=271772 volume=77 Mar 28 16:10:12 volumiopi3 volumio5-onboarding[2290]: time=2026-03-28T16:10:12.219+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.5:46814 @ 0x2504240" id=spotify:track:5inWNELZUTSyzrfibBtt1m title="Towers Open Fire - 2004 Remaster" Mar 28 16:10:12 volumiopi3 volumio5-onboarding[2290]: time=2026-03-28T16:10:12.220+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.5:46814 @ 0x2504240" id=spotify:track:5inWNELZUTSyzrfibBtt1m title="Towers Open Fire - 2004 Remaster" Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: RECEIVED VOLUMIO VOLUME 77 Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: SPOTIFY VOLUME 76 Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: VOLUMIO VOLUME 77 Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: RECEIVED VOLUMIO VOLUME 77 Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: SPOTIFY VOLUME 76 Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: VOLUMIO VOLUME 77 Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 28 16:10:12 volumiopi3 volumio[1226]: info: PeppyMeterBasic ---peppymeterbasic status play Mar 28 16:10:12 volumiopi3 volumio[1226]: info: PeppyMeterBasic ---peppymeterbasic status play Mar 28 16:10:12 volumiopi3 sudo[26796]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Mar 28 16:10:12 volumiopi3 sudo[26796]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:10:12 volumiopi3 sudo[26798]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Mar 28 16:10:12 volumiopi3 sudo[26798]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: PUSH STATE SPOTIFY Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: {"status":"play","service":"spop","title":"This Is the Sea - Live","artist":"The Waterboys","album":"This Is the Sea (Deluxe Version)","albumart":"https://i.scdn.co/image/ab67616d00001e02f74c4e155d96ffed4b759b59","uri":"spotify:track:4d4kYbA548nktAko22mRCp","trackType":"spotify","seek":0,"duration":355,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CoreCommandRouter::servicePushState Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 15 Mar 28 16:10:12 volumiopi3 volumio[1226]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"This Is the Sea - Live","artist":"The Waterboys","album":"This Is the Sea (Deluxe Version)","albumart":"https://i.scdn.co/image/ab67616d00001e02f74c4e155d96ffed4b759b59","uri":"spotify:track:4d4kYbA548nktAko22mRCp","trackType":"spotify","seek":0,"duration":355,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 28 16:10:12 volumiopi3 volumio[1226]: verbose: CURRENT POSITION 15 Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CoreStateMachine::syncState stateService play Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CoreStateMachine::syncState currentStatus play Mar 28 16:10:12 volumiopi3 volumio[1226]: info: Received an update from plugin. extracting info from payload Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CoreStateMachine::pushState Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 15 Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioPushState Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CoreStateMachine::pushState Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 15 Mar 28 16:10:12 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioPushState Mar 28 16:10:12 volumiopi3 volumio5-onboarding[2290]: time=2026-03-28T16:10:12.511+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.5:46814 @ 0x2504240" state=STATUS_PLAYING positionMs=272055 volume=77 Mar 28 16:10:12 volumiopi3 volumio5-onboarding[2290]: time=2026-03-28T16:10:12.512+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.5:46814 @ 0x2504240" id=spotify:track:5inWNELZUTSyzrfibBtt1m title="Towers Open Fire - 2004 Remaster" Mar 28 16:10:12 volumiopi3 volumio5-onboarding[2290]: time=2026-03-28T16:10:12.514+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.5:46814 @ 0x2504240" state=STATUS_PLAYING positionMs=272055 volume=77 Mar 28 16:10:12 volumiopi3 volumio5-onboarding[2290]: time=2026-03-28T16:10:12.515+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.5:46814 @ 0x2504240" id=spotify:track:5inWNELZUTSyzrfibBtt1m title="Towers Open Fire - 2004 Remaster" Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: RECEIVED VOLUMIO VOLUME 77 Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: SPOTIFY VOLUME 76 Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: VOLUMIO VOLUME 77 Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: RECEIVED VOLUMIO VOLUME 77 Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: SPOTIFY VOLUME 76 Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: VOLUMIO VOLUME 77 Mar 28 16:10:12 volumiopi3 volumio[1226]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 28 16:10:12 volumiopi3 sudo[26796]: pam_unix(sudo:session): session closed for user root Mar 28 16:10:12 volumiopi3 volumio[1226]: info: PeppyMeterBasic ---peppymeterbasic status play Mar 28 16:10:12 volumiopi3 sudo[26798]: pam_unix(sudo:session): session closed for user root Mar 28 16:10:12 volumiopi3 volumio[1226]: info: PeppyMeterBasic ---peppymeterbasic status play Mar 28 16:10:12 volumiopi3 volumio[1226]: info: peppymeterbasic Daemon Started Mar 28 16:10:12 volumiopi3 volumio[1226]: info: peppymeterbasic Daemon Started Mar 28 16:10:12 volumiopi3 sudo[26802]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Mar 28 16:10:12 volumiopi3 sudo[26802]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:10:12 volumiopi3 sudo[26804]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Mar 28 16:10:12 volumiopi3 sudo[26804]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:10:12 volumiopi3 sudo[26802]: pam_unix(sudo:session): session closed for user root Mar 28 16:10:12 volumiopi3 volumio[1226]: info: peppymeterbasic Daemon Started Mar 28 16:10:12 volumiopi3 sudo[26804]: pam_unix(sudo:session): session closed for user root Mar 28 16:10:12 volumiopi3 volumio[1226]: info: peppymeterbasic Daemon Started Mar 28 16:10:14 volumiopi3 volumio[1226]: info: CoreStateMachine::startPlaybackTimer Mar 28 16:10:14 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:10:15 volumiopi3 volumio[1226]: info: CoreStateMachine::pushState Mar 28 16:10:15 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:10:15 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 16:10:15 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioPushState Mar 28 16:10:15 volumiopi3 volumio5-onboarding[2290]: time=2026-03-28T16:10:15.252+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.5:46814 @ 0x2504240" state=STATUS_PLAYING positionMs=251 volume=77 Mar 28 16:10:15 volumiopi3 volumio5-onboarding[2290]: time=2026-03-28T16:10:15.257+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.5:46814 @ 0x2504240" id=spotify:track:4d4kYbA548nktAko22mRCp title="This Is the Sea - Live / 2004 Remaster" Mar 28 16:10:15 volumiopi3 volumio[1226]: SPOTIFY: RECEIVED VOLUMIO VOLUME 77 Mar 28 16:10:15 volumiopi3 volumio[1226]: SPOTIFY: SPOTIFY VOLUME 76 Mar 28 16:10:15 volumiopi3 volumio[1226]: SPOTIFY: VOLUMIO VOLUME 77 Mar 28 16:10:15 volumiopi3 volumio[1226]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 28 16:10:15 volumiopi3 volumio[1226]: info: PeppyMeterBasic ---peppymeterbasic status play Mar 28 16:10:15 volumiopi3 sudo[26808]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Mar 28 16:10:15 volumiopi3 sudo[26808]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:10:15 volumiopi3 sudo[26808]: pam_unix(sudo:session): session closed for user root Mar 28 16:10:15 volumiopi3 volumio[1226]: info: peppymeterbasic Daemon Started Mar 28 16:10:23 volumiopi3 sudo[26825]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 28 16:10:23 volumiopi3 sudo[26825]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:10:23 volumiopi3 sudo[26825]: pam_unix(sudo:session): session closed for user root Mar 28 16:10:23 volumiopi3 sudo[26827]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 28 16:10:23 volumiopi3 sudo[26827]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:10:23 volumiopi3 sudo[26827]: pam_unix(sudo:session): session closed for user root Mar 28 16:10:23 volumiopi3 volumio[1226]: verbose: New Socket.io Connection to 192.168.1.64 from 192.168.1.5 UA: Mozilla/5.0 (Linux; Android 15; 23108RN04Y Build/AP3A.240905.015.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.164 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 15 Mar 28 16:10:23 volumiopi3 sudo[26832]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 28 16:10:23 volumiopi3 sudo[26832]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:10:23 volumiopi3 sudo[26832]: pam_unix(sudo:session): session closed for user root Mar 28 16:10:23 volumiopi3 sudo[26834]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 28 16:10:23 volumiopi3 sudo[26834]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:10:23 volumiopi3 sudo[26834]: pam_unix(sudo:session): session closed for user root Mar 28 16:10:23 volumiopi3 volumio[1226]: verbose: New Socket.io Connection to 192.168.1.64 from 192.168.1.5 UA: Mozilla/5.0 (Linux; Android 15; 23108RN04Y Build/AP3A.240905.015.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.164 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 16 Mar 28 16:10:24 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 28 16:10:24 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioGetVisibleSources Mar 28 16:10:24 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 16:10:24 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioGetState Mar 28 16:10:24 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:10:24 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 28 16:10:24 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 28 16:10:24 volumiopi3 volumio[1226]: info: Received Get System Info Mar 28 16:10:24 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 16:10:24 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 16:10:24 volumiopi3 volumio[1226]: info: Discovery: Getting this device information Mar 28 16:10:24 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioGetState Mar 28 16:10:24 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:10:24 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 16:10:24 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioGetState Mar 28 16:10:24 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:10:24 volumiopi3 volumio[1226]: info: Listing playlists Mar 28 16:10:24 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 28 16:10:24 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 28 16:10:24 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 28 16:10:24 volumiopi3 volumio[1226]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 16:10:24 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:24+01:00" level=debug msg="fetched chunk 4/29, size: 524288" uri="spotify:track:4d4kYbA548nktAko22mRCp" Mar 28 16:10:25 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 16:10:25 volumiopi3 volumio[1226]: info: Received Get System Info Mar 28 16:10:25 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 16:10:25 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 16:10:25 volumiopi3 volumio[1226]: info: Discovery: Getting this device information Mar 28 16:10:25 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioGetState Mar 28 16:10:25 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:10:25 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 16:10:26 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Mar 28 16:10:26 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 16:10:26 volumiopi3 volumio[1226]: info: Received Get System Info Mar 28 16:10:26 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 16:10:26 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 16:10:26 volumiopi3 volumio[1226]: info: Discovery: Getting this device information Mar 28 16:10:26 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioGetState Mar 28 16:10:26 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:10:26 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 16:10:29 volumiopi3 volumio5-onboarding[2290]: time=2026-03-28T16:10:29.434+01:00 level=ERROR msg="failed to cancel pairing for disconnected device" component=ble/conn device=A4:E2:87:32:93:35 error="Method \"CancelPairing\" with signature \"\" on interface \"org.bluez.Device1\" doesn't exist\n" Mar 28 16:10:33 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Mar 28 16:10:35 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 16:10:35 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 28 16:10:35 volumiopi3 volumio[1226]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 16:10:36 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:36+01:00" level=debug msg="fetched chunk 5/29, size: 524288" uri="spotify:track:4d4kYbA548nktAko22mRCp" Mar 28 16:10:37 volumiopi3 volumio5-onboarding[2290]: time=2026-03-28T16:10:37.453+01:00 level=ERROR msg="failed to cancel pairing for disconnected device" component=ble/conn device=A4:E2:87:32:93:35 error="Method \"CancelPairing\" with signature \"\" on interface \"org.bluez.Device1\" doesn't exist\n" Mar 28 16:10:38 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:38+01:00" level=trace msg="received accesspoint ping" Mar 28 16:10:38 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:38+01:00" level=trace msg="received accesspoint pong ack" Mar 28 16:10:38 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:38+01:00" level=trace msg="sent dealer ping" Mar 28 16:10:38 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:38+01:00" level=trace msg="received dealer pong" Mar 28 16:10:41 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 28 16:10:41 volumiopi3 volumio[1226]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Mar 28 16:10:41 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Mar 28 16:10:41 volumiopi3 volumio[1226]: info: Received Get System Version Mar 28 16:10:41 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 16:10:41 volumiopi3 volumio[1226]: info: Received Get System Info Mar 28 16:10:41 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 16:10:41 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 16:10:41 volumiopi3 volumio[1226]: info: Discovery: Getting this device information Mar 28 16:10:41 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioGetState Mar 28 16:10:41 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:10:41 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 16:10:42 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 16:10:42 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 16:10:42 volumiopi3 volumio[1226]: info: Discovery: Getting this device information Mar 28 16:10:42 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioGetState Mar 28 16:10:42 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:10:42 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 16:10:42 volumiopi3 volumio[1226]: verbose: New Socket.io Connection to 192.168.1.64:3000 from 192.168.1.5 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 17 Mar 28 16:10:42 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 16:10:42 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 16:10:47 volumiopi3 volumio5-onboarding[2290]: time=2026-03-28T16:10:47.931+01:00 level=ERROR msg="failed to cancel pairing for disconnected device" component=ble/conn device=A4:E2:87:32:93:35 error="Method \"CancelPairing\" with signature \"\" on interface \"org.bluez.Device1\" doesn't exist\n" Mar 28 16:10:48 volumiopi3 go-librespot[1715]: time="2026-03-28T16:10:48+01:00" level=debug msg="fetched chunk 6/29, size: 524288" uri="spotify:track:4d4kYbA548nktAko22mRCp" Mar 28 16:10:48 volumiopi3 sudo[26886]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 28 16:10:48 volumiopi3 sudo[26886]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:10:48 volumiopi3 sudo[26886]: pam_unix(sudo:session): session closed for user root Mar 28 16:10:48 volumiopi3 sudo[26888]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 28 16:10:48 volumiopi3 sudo[26888]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:10:48 volumiopi3 sudo[26888]: pam_unix(sudo:session): session closed for user root Mar 28 16:10:48 volumiopi3 volumio[1226]: verbose: New Socket.io Connection to 192.168.1.64 from 192.168.1.5 UA: Mozilla/5.0 (Linux; Android 15; 23108RN04Y Build/AP3A.240905.015.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.164 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 17 Mar 28 16:10:49 volumiopi3 sudo[26893]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 28 16:10:49 volumiopi3 sudo[26893]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:10:49 volumiopi3 sudo[26893]: pam_unix(sudo:session): session closed for user root Mar 28 16:10:49 volumiopi3 sudo[26895]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 28 16:10:49 volumiopi3 sudo[26895]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:10:49 volumiopi3 sudo[26895]: pam_unix(sudo:session): session closed for user root Mar 28 16:10:49 volumiopi3 volumio[1226]: verbose: New Socket.io Connection to 192.168.1.64 from 192.168.1.5 UA: Mozilla/5.0 (Linux; Android 15; 23108RN04Y Build/AP3A.240905.015.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.164 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 18 Mar 28 16:10:49 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 28 16:10:49 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioGetVisibleSources Mar 28 16:10:49 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 16:10:49 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioGetState Mar 28 16:10:49 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:10:49 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 28 16:10:49 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 28 16:10:49 volumiopi3 volumio[1226]: info: Received Get System Info Mar 28 16:10:49 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 16:10:49 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 16:10:49 volumiopi3 volumio[1226]: info: Discovery: Getting this device information Mar 28 16:10:49 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioGetState Mar 28 16:10:49 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:10:49 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 16:10:49 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioGetState Mar 28 16:10:49 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:10:49 volumiopi3 volumio[1226]: info: Listing playlists Mar 28 16:10:49 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 28 16:10:49 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 28 16:10:49 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 28 16:10:49 volumiopi3 volumio[1226]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 16:10:51 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 16:10:51 volumiopi3 volumio[1226]: info: Received Get System Info Mar 28 16:10:51 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 16:10:51 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 16:10:51 volumiopi3 volumio[1226]: info: Discovery: Getting this device information Mar 28 16:10:51 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioGetState Mar 28 16:10:51 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:10:51 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 16:10:51 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Mar 28 16:10:52 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 16:10:52 volumiopi3 volumio[1226]: info: Received Get System Info Mar 28 16:10:52 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 16:10:52 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 16:10:52 volumiopi3 volumio[1226]: info: Discovery: Getting this device information Mar 28 16:10:52 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioGetState Mar 28 16:10:52 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:10:52 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 16:10:52 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 16:10:52 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 28 16:10:52 volumiopi3 volumio[1226]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 16:10:59 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Mar 28 16:11:00 volumiopi3 go-librespot[1715]: time="2026-03-28T16:11:00+01:00" level=debug msg="fetched chunk 7/29, size: 524288" uri="spotify:track:4d4kYbA548nktAko22mRCp" Mar 28 16:11:02 volumiopi3 volumio[1226]: info: Stopping peppymeterbasic service Mar 28 16:11:02 volumiopi3 volumio[1226]: info: CoreStateMachine::stop Mar 28 16:11:02 volumiopi3 volumio[1226]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 16:11:02 volumiopi3 volumio[1226]: info: CoreStateMachine::stPlaybackTimer Mar 28 16:11:02 volumiopi3 volumio[1226]: info: CoreStateMachine::updateTrackBlock Mar 28 16:11:02 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrackBlock Mar 28 16:11:02 volumiopi3 volumio[1226]: info: CoreStateMachine::pushState Mar 28 16:11:02 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:11:02 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 16:11:02 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioPushState Mar 28 16:11:02 volumiopi3 volumio[1226]: info: CoreStateMachine::serviceStop Mar 28 16:11:02 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:11:02 volumiopi3 volumio[1226]: info: CoreCommandRouter::serviceStop Mar 28 16:11:02 volumiopi3 volumio[1226]: info: Spotify Stop Mar 28 16:11:02 volumiopi3 volumio[1226]: SPOTIFY: SPOTIFY STOP Mar 28 16:11:02 volumiopi3 volumio[1226]: SPOTIFY: {"status":"play","position":16,"title":"This Is the Sea - Live / 2004 Remaster","artist":"The Waterboys","album":"This Is the Sea (Deluxe Version)","albumart":"https://i.scdn.co/image/ab67616d0000b273e6e127ff66aee167d67e794a","uri":"spotify:track:4d4kYbA548nktAko22mRCp","trackType":"spotify","codec":"ogg","seek":251,"duration":355,"samplerate":"320 kbps","bitdepth":"16 bit","random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":77,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Mar 28 16:11:02 volumiopi3 volumio[1226]: info: Sending Spotify command to local API: /player/pause Mar 28 16:11:02 volumiopi3 volumio[1226]: info: Disabling plugin peppymeterbasic Mar 28 16:11:02 volumiopi3 volumio[1226]: info: Preparing to generate the ALSA configuration file Mar 28 16:11:02 volumiopi3 volumio5-onboarding[2290]: time=2026-03-28T16:11:02.112+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.5:46814 @ 0x2504240" state=STATUS_STOPPED positionMs=0 volume=77 Mar 28 16:11:02 volumiopi3 volumio5-onboarding[2290]: time=2026-03-28T16:11:02.113+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.5:46814 @ 0x2504240" id=spotify:track:4d4kYbA548nktAko22mRCp title="This Is the Sea - Live / 2004 Remaster" Mar 28 16:11:02 volumiopi3 sudo[26915]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Mar 28 16:11:02 volumiopi3 sudo[26915]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:02 volumiopi3 systemd[1]: Stopping peppymeterbasic.service - peppymeterbasic Daemon... Mar 28 16:11:02 volumiopi3 volumio[1226]: SPOTIFY: RECEIVED VOLUMIO VOLUME 77 Mar 28 16:11:02 volumiopi3 volumio[1226]: SPOTIFY: SPOTIFY VOLUME 76 Mar 28 16:11:02 volumiopi3 volumio[1226]: SPOTIFY: VOLUMIO VOLUME 77 Mar 28 16:11:02 volumiopi3 volumio[1226]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 28 16:11:02 volumiopi3 volumio[1226]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Mar 28 16:11:02 volumiopi3 volumio[1226]: info: Reading ALSA contributions from plugins. Mar 28 16:11:02 volumiopi3 go-librespot[1715]: time="2026-03-28T16:11:02+01:00" level=debug msg="pause track at 50334ms" Mar 28 16:11:02 volumiopi3 volumio[1226]: info: Asound.conf file written Mar 28 16:11:02 volumiopi3 systemd[1]: peppymeterbasic.service: Deactivated successfully. Mar 28 16:11:02 volumiopi3 systemd[1]: Stopped peppymeterbasic.service - peppymeterbasic Daemon. Mar 28 16:11:02 volumiopi3 systemd[1]: peppymeterbasic.service: Consumed 22.104s CPU time. Mar 28 16:11:02 volumiopi3 sudo[26923]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Mar 28 16:11:02 volumiopi3 sudo[26923]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:02 volumiopi3 go-librespot[1715]: time="2026-03-28T16:11:02+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 16:11:02 volumiopi3 sudo[26923]: pam_unix(sudo:session): session closed for user root Mar 28 16:11:02 volumiopi3 go-librespot[1715]: time="2026-03-28T16:11:02+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 16:11:02 volumiopi3 go-librespot[1715]: time="2026-03-28T16:11:02+01:00" level=trace msg="emitting websocket event: paused" Mar 28 16:11:03 volumiopi3 volumio[1226]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Mar 28 16:11:03 volumiopi3 volumio[1226]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Mar 28 16:11:03 volumiopi3 volumio[1226]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Mar 28 16:11:03 volumiopi3 volumio[1226]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:3 use case configuration -2 Mar 28 16:11:03 volumiopi3 volumio[1226]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:Max Overclock PLL:0' : Device or resource busy Mar 28 16:11:03 volumiopi3 volumio[1226]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:Max Overclock DSP:0' : Device or resource busy Mar 28 16:11:03 volumiopi3 volumio[1226]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:Max Overclock DAC:0' : Device or resource busy Mar 28 16:11:03 volumiopi3 volumio[1226]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:7 use case configuration -2 Mar 28 16:11:03 volumiopi3 volumio[1226]: info: Output device has changed, restarting MPD Mar 28 16:11:03 volumiopi3 volumio[1226]: info: Output device has changed, restarting Shairport Sync Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 16:11:03 volumiopi3 sudo[26915]: pam_unix(sudo:session): session closed for user root Mar 28 16:11:03 volumiopi3 sudo[26930]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 28 16:11:03 volumiopi3 sudo[26930]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:03 volumiopi3 sudo[26933]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 28 16:11:03 volumiopi3 sudo[26930]: pam_unix(sudo:session): session closed for user root Mar 28 16:11:03 volumiopi3 sudo[26933]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:03 volumiopi3 volumio[1226]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 28 16:11:03 volumiopi3 volumio[1226]: info: Done. Mar 28 16:11:03 volumiopi3 systemd[1]: Stopping mpd.service - Music Player Daemon... Mar 28 16:11:03 volumiopi3 sudo[26942]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Mar 28 16:11:03 volumiopi3 sudo[26942]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:03 volumiopi3 volumio[1226]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:6uPaSEHsa9NQMa94IrdKAg","uri":"spotify:track:4d4kYbA548nktAko22mRCp","play_origin":"go-librespot"}} Mar 28 16:11:03 volumiopi3 volumio[1226]: SPOTIFY: PUSH STATE SPOTIFY Mar 28 16:11:03 volumiopi3 volumio[1226]: SPOTIFY: {"status":"pause","service":"spop","title":"This Is the Sea - Live","artist":"The Waterboys","album":"This Is the Sea (Deluxe Version)","albumart":"https://i.scdn.co/image/ab67616d00001e02f74c4e155d96ffed4b759b59","uri":"spotify:track:4d4kYbA548nktAko22mRCp","trackType":"spotify","seek":50000,"duration":355,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreCommandRouter::servicePushState Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:11:03 volumiopi3 volumio[1226]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"This Is the Sea - Live","artist":"The Waterboys","album":"This Is the Sea (Deluxe Version)","albumart":"https://i.scdn.co/image/ab67616d00001e02f74c4e155d96ffed4b759b59","uri":"spotify:track:4d4kYbA548nktAko22mRCp","trackType":"spotify","seek":50000,"duration":355,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 28 16:11:03 volumiopi3 volumio[1226]: verbose: CURRENT POSITION 16 Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreStateMachine::syncState stateService pause Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreStateMachine::syncState currentStatus stop Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreStateMachine::pushState Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioPushState Mar 28 16:11:03 volumiopi3 vtcs[25845]: [2026-03-28 16:11:03.350] [tisoc] [error] [SpkconServer.cpp:378] recv error. socket disconnected Mar 28 16:11:03 volumiopi3 vtcs[25845]: [2026-03-28 16:11:03.452] [tisoc] [warning] [SessionManagerImpl.cpp:240] Illegal State: IDLE Mar 28 16:11:03 volumiopi3 volumio5-onboarding[2290]: time=2026-03-28T16:11:03.490+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.5:46814 @ 0x2504240" state=STATUS_STOPPED positionMs=503 volume=77 Mar 28 16:11:03 volumiopi3 volumio5-onboarding[2290]: time=2026-03-28T16:11:03.490+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.5:46814 @ 0x2504240" id=spotify:track:4d4kYbA548nktAko22mRCp title="This Is the Sea - Live / 2004 Remaster" Mar 28 16:11:03 volumiopi3 sudo[26946]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Mar 28 16:11:03 volumiopi3 sudo[26946]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:03 volumiopi3 volumio[1226]: info: MPD Permissions set Mar 28 16:11:03 volumiopi3 volumio[1226]: info: touch_display: Setting screensaver timeout to 120 seconds. Mar 28 16:11:03 volumiopi3 volumio[1226]: SPOTIFY: RECEIVED VOLUMIO VOLUME 77 Mar 28 16:11:03 volumiopi3 volumio[1226]: SPOTIFY: SPOTIFY VOLUME 76 Mar 28 16:11:03 volumiopi3 volumio[1226]: SPOTIFY: VOLUMIO VOLUME 77 Mar 28 16:11:03 volumiopi3 volumio[1226]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 28 16:11:03 volumiopi3 systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 16:11:03 volumiopi3 systemd[1]: vtcs.service: Deactivated successfully. Mar 28 16:11:03 volumiopi3 systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Mar 28 16:11:03 volumiopi3 systemd[1]: vtcs.service: Consumed 2.029s CPU time. Mar 28 16:11:03 volumiopi3 volumio[1226]: info: camilladsp respawn in 100 ms (attempt 1/10) Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:03 volumiopi3 sudo[26942]: pam_unix(sudo:session): session closed for user root Mar 28 16:11:03 volumiopi3 sudo[26946]: pam_unix(sudo:session): session closed for user root Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 16:11:03 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:04 volumiopi3 volumio[1226]: info: Starting Shairport Sync Mar 28 16:11:04 volumiopi3 sudo[26957]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 28 16:11:04 volumiopi3 sudo[26957]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:04 volumiopi3 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 28 16:11:04 volumiopi3 systemd[1]: shairport-sync.service: Deactivated successfully. Mar 28 16:11:04 volumiopi3 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 28 16:11:04 volumiopi3 systemd[1]: shairport-sync.service: Consumed 7.651s CPU time. Mar 28 16:11:04 volumiopi3 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 28 16:11:04 volumiopi3 sudo[26957]: pam_unix(sudo:session): session closed for user root Mar 28 16:11:04 volumiopi3 volumio[1226]: info: Shairport-Sync Started Mar 28 16:11:06 volumiopi3 volumio[1226]: info: Enabling plugin peppymeterbasic Mar 28 16:11:06 volumiopi3 volumio[1226]: info: Loading plugin "peppymeterbasic"... Mar 28 16:11:06 volumiopi3 volumio[1226]: info: Preparing to generate the ALSA configuration file Mar 28 16:11:06 volumiopi3 volumio[1226]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Mar 28 16:11:06 volumiopi3 volumio[1226]: info: The plugin peppymeterbasic has an ALSA contribution file peppy_in.peppy_out.6.conf Mar 28 16:11:06 volumiopi3 volumio[1226]: info: Reading ALSA contributions from plugins. Mar 28 16:11:06 volumiopi3 volumio[1226]: info: Asound.conf file written Mar 28 16:11:06 volumiopi3 sudo[26993]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Mar 28 16:11:06 volumiopi3 sudo[26993]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:06 volumiopi3 sudo[26993]: pam_unix(sudo:session): session closed for user root Mar 28 16:11:06 volumiopi3 systemd[1]: mpd.service: Deactivated successfully. Mar 28 16:11:06 volumiopi3 systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 28 16:11:06 volumiopi3 systemd[1]: mpd.service: Consumed 10.490s CPU time. Mar 28 16:11:06 volumiopi3 systemd[1]: mpd.socket: Deactivated successfully. Mar 28 16:11:06 volumiopi3 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 28 16:11:06 volumiopi3 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 28 16:11:06 volumiopi3 volumio[1226]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Mar 28 16:11:06 volumiopi3 volumio[1226]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Mar 28 16:11:06 volumiopi3 volumio[1226]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Mar 28 16:11:06 volumiopi3 volumio[1226]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:3 use case configuration -2 Mar 28 16:11:06 volumiopi3 volumio[1226]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:Max Overclock PLL:0' : Device or resource busy Mar 28 16:11:06 volumiopi3 volumio[1226]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:Max Overclock DSP:0' : Device or resource busy Mar 28 16:11:06 volumiopi3 volumio[1226]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:Max Overclock DAC:0' : Device or resource busy Mar 28 16:11:06 volumiopi3 volumio[1226]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:7 use case configuration -2 Mar 28 16:11:06 volumiopi3 volumio[1226]: info: Output device has changed, restarting MPD Mar 28 16:11:06 volumiopi3 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 28 16:11:06 volumiopi3 volumio[1226]: info: Output device has changed, restarting Shairport Sync Mar 28 16:11:06 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:06 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 16:11:06 volumiopi3 sudo[27002]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 28 16:11:06 volumiopi3 sudo[27002]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:06 volumiopi3 sudo[27002]: pam_unix(sudo:session): session closed for user root Mar 28 16:11:06 volumiopi3 sudo[27004]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 28 16:11:06 volumiopi3 sudo[27004]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:06 volumiopi3 volumio[1226]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 28 16:11:06 volumiopi3 volumio[1226]: info: PLUGIN START: peppymeterbasic Mar 28 16:11:06 volumiopi3 systemd[1]: Starting mpd.service - Music Player Daemon... Mar 28 16:11:06 volumiopi3 sudo[27013]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Mar 28 16:11:06 volumiopi3 sudo[27013]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:06 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Mar 28 16:11:06 volumiopi3 systemd[1]: mpd.service: Deactivated successfully. Mar 28 16:11:06 volumiopi3 systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 28 16:11:06 volumiopi3 systemd[1]: mpd.socket: Deactivated successfully. Mar 28 16:11:06 volumiopi3 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 28 16:11:06 volumiopi3 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 28 16:11:06 volumiopi3 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 28 16:11:06 volumiopi3 volumio[1226]: info: Preparing to generate the ALSA configuration file Mar 28 16:11:07 volumiopi3 systemd[1]: Starting mpd.service - Music Player Daemon... Mar 28 16:11:07 volumiopi3 sudo[27016]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/modprobe snd_aloop index=7 pcm_substreams=2 Mar 28 16:11:07 volumiopi3 sudo[27016]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:07 volumiopi3 volumio[1226]: info: Done. Mar 28 16:11:07 volumiopi3 volumio[1226]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Mar 28 16:11:07 volumiopi3 volumio[1226]: info: The plugin peppymeterbasic has an ALSA contribution file peppy_in.peppy_out.6.conf Mar 28 16:11:07 volumiopi3 volumio[1226]: info: Reading ALSA contributions from plugins. Mar 28 16:11:07 volumiopi3 volumio[1226]: info: MPD Permissions set Mar 28 16:11:07 volumiopi3 volumio[1226]: info: TidalConnect service stoped! Mar 28 16:11:07 volumiopi3 volumio[1226]: info: TidalConnect service stoped! Mar 28 16:11:07 volumiopi3 sudo[27013]: pam_unix(sudo:session): session closed for user root Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 16:11:07 volumiopi3 sudo[27021]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Mar 28 16:11:07 volumiopi3 sudo[27021]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:07 volumiopi3 volumio[1226]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 17 Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:07 volumiopi3 sudo[27016]: pam_unix(sudo:session): session closed for user root Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:07 volumiopi3 sudo[27021]: pam_unix(sudo:session): session closed for user root Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Mar 28 16:11:07 volumiopi3 volumio[1226]: info: Received Get System Version Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 16:11:07 volumiopi3 volumio[1226]: info: Received Get System Info Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 16:11:07 volumiopi3 volumio[1226]: info: Discovery: Getting this device information Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CoreCommandRouter::volumioGetState Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CorePlayQueue::getTrack 16 Mar 28 16:11:07 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 16:11:07 volumiopi3 sudo[27018]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 28 16:11:07 volumiopi3 sudo[27018]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 28 16:11:07 volumiopi3 sudo[27018]: pam_unix(sudo:session): session closed for user root Mar 28 16:11:07 volumiopi3 volumio[1226]: info: snd_dummy loaded Mar 28 16:11:07 volumiopi3 volumio[1226]: info: Starting Shairport Sync Mar 28 16:11:08 volumiopi3 sudo[27041]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 28 16:11:08 volumiopi3 sudo[27041]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:08 volumiopi3 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 28 16:11:08 volumiopi3 systemd[1]: shairport-sync.service: Deactivated successfully. Mar 28 16:11:08 volumiopi3 volumio[1226]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Mar 28 16:11:08 volumiopi3 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 28 16:11:08 volumiopi3 volumio[1226]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect Mar 28 16:11:08 volumiopi3 systemd[1]: shairport-sync.service: Consumed 1.987s CPU time. Mar 28 16:11:08 volumiopi3 volumio[1226]: info: Asound.conf file unchanged, so no further update is needed Mar 28 16:11:08 volumiopi3 volumio[1226]: info: Output device has changed, restarting MPD Mar 28 16:11:08 volumiopi3 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 28 16:11:08 volumiopi3 volumio[1226]: info: Output device has changed, restarting Shairport Sync Mar 28 16:11:08 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:08 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 16:11:08 volumiopi3 sudo[27041]: pam_unix(sudo:session): session closed for user root Mar 28 16:11:08 volumiopi3 sudo[27046]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 28 16:11:08 volumiopi3 sudo[27046]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:08 volumiopi3 sudo[27046]: pam_unix(sudo:session): session closed for user root Mar 28 16:11:08 volumiopi3 sudo[27049]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 28 16:11:08 volumiopi3 sudo[27049]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:08 volumiopi3 volumio[1226]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 28 16:11:08 volumiopi3 go-librespot[1715]: time="2026-03-28T16:11:08+01:00" level=trace msg="sent dealer ping" Mar 28 16:11:08 volumiopi3 go-librespot[1715]: time="2026-03-28T16:11:08+01:00" level=trace msg="received dealer pong" Mar 28 16:11:08 volumiopi3 sudo[27056]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Mar 28 16:11:08 volumiopi3 sudo[27056]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:08 volumiopi3 systemd[1]: mpd.service: Deactivated successfully. Mar 28 16:11:08 volumiopi3 systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 28 16:11:08 volumiopi3 systemd[1]: mpd.service: Consumed 1.080s CPU time. Mar 28 16:11:08 volumiopi3 systemd[1]: mpd.socket: Deactivated successfully. Mar 28 16:11:08 volumiopi3 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 28 16:11:08 volumiopi3 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 28 16:11:08 volumiopi3 sudo[27077]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Mar 28 16:11:08 volumiopi3 sudo[27077]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:08 volumiopi3 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 28 16:11:08 volumiopi3 volumio[1226]: info: MPD Permissions set Mar 28 16:11:08 volumiopi3 volumio[1226]: info: Shairport-Sync Started Mar 28 16:11:08 volumiopi3 systemd[1]: Starting mpd.service - Music Player Daemon... Mar 28 16:11:08 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:08 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:08 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:08 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:08 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:08 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:08 volumiopi3 sudo[27079]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Mar 28 16:11:08 volumiopi3 sudo[27079]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 16:11:08 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:08 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:08 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 16:11:08 volumiopi3 volumio[1226]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 16:11:08 volumiopi3 sudo[27077]: pam_unix(sudo:session): session closed for user root Mar 28 16:11:08 volumiopi3 sudo[27056]: pam_unix(sudo:session): session closed for user root Mar 28 16:11:08 volumiopi3 systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Mar 28 16:11:08 volumiopi3 sudo[27079]: pam_unix(sudo:session): session closed for user root Mar 28 16:11:09 volumiopi3 volumio[1226]: error: Error starting TidalConnect Command failed: /usr/bin/sudo /bin/systemctl stop vtcs.service && sleep 3 Mar 28 16:11:09 volumiopi3 volumio[1226]: Job for vtcs.service canceled. Mar 28 16:11:09 volumiopi3 volumio[1226]: {"cmd":"/usr/bin/sudo /bin/systemctl stop vtcs.service && sleep 3","code":1,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/bin/sudo /bin/systemctl stop vtcs.service && sleep 3\nJob for vtcs.service canceled.\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)","stderr":"Job for vtcs.service canceled.\n","stdout":""} Mar 28 16:11:09 volumiopi3 volumio[1226]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 28 16:11:09 volumiopi3 volumio[1226]: Error: Command failed: /usr/bin/sudo /bin/systemctl stop vtcs.service && sleep 3 Mar 28 16:11:09 volumiopi3 volumio[1226]: Job for vtcs.service canceled. Mar 28 16:11:09 volumiopi3 volumio[1226]: at ChildProcess.exithandler (node:child_process:421:12) Mar 28 16:11:09 volumiopi3 volumio[1226]: at ChildProcess.emit (node:events:514:28) Mar 28 16:11:09 volumiopi3 volumio[1226]: at maybeClose (node:internal/child_process:1105:16) Mar 28 16:11:09 volumiopi3 volumio[1226]: at Socket. (node:internal/child_process:457:11) Mar 28 16:11:09 volumiopi3 volumio[1226]: at Socket.emit (node:events:514:28) Mar 28 16:11:09 volumiopi3 volumio[1226]: at Pipe. (node:net:337:12) { Mar 28 16:11:09 volumiopi3 volumio[1226]: code: 1, Mar 28 16:11:09 volumiopi3 volumio[1226]: killed: false, Mar 28 16:11:09 volumiopi3 volumio[1226]: signal: null, Mar 28 16:11:09 volumiopi3 volumio[1226]: cmd: '/usr/bin/sudo /bin/systemctl stop vtcs.service && sleep 3', Mar 28 16:11:09 volumiopi3 volumio[1226]: stdout: '', Mar 28 16:11:09 volumiopi3 volumio[1226]: stderr: 'Job for vtcs.service canceled.\n' Mar 28 16:11:09 volumiopi3 volumio[1226]: } Mar 28 16:11:09 volumiopi3 volumio[1226]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 28 16:11:09 volumiopi3 sudo[27081]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 28 16:11:09 volumiopi3 sudo[27081]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 28 16:11:09 volumiopi3 sudo[27081]: pam_unix(sudo:session): session closed for user root Mar 28 16:11:14 volumiopi3 sudo[27108]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-28 16:10' Mar 28 16:11:14 volumiopi3 sudo[27108]: 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"