-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Sun 2025-05-11 14:12:12 CEST. -- May 11 14:11:00 volumio go-librespot[2019]: time="2025-05-11T14:11:00+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1126" May 11 14:11:00 volumio go-librespot[2019]: time="2025-05-11T14:11:00+02:00" level=debug msg="fetched first chunk of 13, total size is 6476029 bytes" uri="spotify:track:4FKDsKzzA0UhvAvoQm7EgT" May 11 14:11:00 volumio go-librespot[2019]: time="2025-05-11T14:11:00+02:00" level=debug msg="fetched chunk 1/12, size: 524288" uri="spotify:track:4FKDsKzzA0UhvAvoQm7EgT" May 11 14:11:00 volumio go-librespot[2019]: time="2025-05-11T14:11:00+02:00" level=debug msg="fetched chunk 8/12, size: 524288" uri="spotify:track:4FKDsKzzA0UhvAvoQm7EgT" May 11 14:11:00 volumio go-librespot[2019]: time="2025-05-11T14:11:00+02:00" level=trace msg="seek to 97593ms (diff: 132ms, samples: 4303851, bytes: 4354886)" uri="spotify:track:4FKDsKzzA0UhvAvoQm7EgT" May 11 14:11:00 volumio go-librespot[2019]: time="2025-05-11T14:11:00+02:00" level=debug msg="created new output device" May 11 14:11:00 volumio go-librespot[2019]: time="2025-05-11T14:11:00+02:00" level=info msg="loaded track \"Mr. Mellow (Always Remember Us This Way)\" (paused: true, position: 97593ms, duration: 146991ms, prefetched: false)" uri="spotify:track:4FKDsKzzA0UhvAvoQm7EgT" May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=trace msg="emitting websocket event: metadata" May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=trace msg="emitting websocket event: active" May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=debug msg="sending successful reply for dealer request" May 11 14:11:01 volumio volumio[1849]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4FKDsKzzA0UhvAvoQm7EgT","name":"Mr. Mellow (Always Remember Us This Way)","artist_names":["Mr. Mellow"],"album_name":"Mr. Mellow (Always Remember Us This Way)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02c1a8fbc85fc4417cff99c9a0","position":97593,"duration":146991,"release_date":"year:2024 month:4 day:29","track_number":1,"disc_number":1}} May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 11 14:11:01 volumio volumio[1849]: SPOTIFY: received: {"type":"active","data":null} May 11 14:11:01 volumio volumio[1849]: info: Aligning Spotify Volume to Volumio Volume May 11 14:11:01 volumio volumio[1849]: info: CoreCommandRouter::volumioGetState May 11 14:11:01 volumio volumio[1849]: info: CorePlayQueue::getTrack 0 May 11 14:11:01 volumio volumio[1849]: info: Setting Spotify Volume from Volumio: 0 May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=debug msg="fetched chunk 2/12, size: 524288" uri="spotify:track:4FKDsKzzA0UhvAvoQm7EgT" May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=debug msg="fetched chunk 11/12, size: 524288" uri="spotify:track:4FKDsKzzA0UhvAvoQm7EgT" May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=debug msg="fetched chunk 10/12, size: 524288" uri="spotify:track:4FKDsKzzA0UhvAvoQm7EgT" May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=debug msg="fetched chunk 3/12, size: 524288" uri="spotify:track:4FKDsKzzA0UhvAvoQm7EgT" May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=trace msg="emitting websocket event: paused" May 11 14:11:01 volumio volumio[1849]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:4FKDsKzzA0UhvAvoQm7EgT","play_origin":"com.spotify.service.carplayv2"}} May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=debug msg="handling resume player command from b646b1402e3e1d7c0767f15c2f7949604c73f8a8" May 11 14:11:01 volumio volumio[1849]: info: Spotify is playing in volatile mode May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=trace msg="seek to 97593ms (diff: 132ms, samples: 4303851, bytes: 4354886)" uri="spotify:track:4FKDsKzzA0UhvAvoQm7EgT" May 11 14:11:01 volumio volumio[1849]: info: CoreStateMachine::setConsumeUpdateService undefined May 11 14:11:01 volumio volumio[1849]: SPOTIFY: UNSET VOLATILE May 11 14:11:01 volumio volumio[1849]: SPOTIFY: {"status":"stop","position":0,"title":"Pedro","artist":"Jaxomy","album":"Pedro","albumart":"https://i.scdn.co/image/ab67616d0000b273df8680015ddf76e5c444849f","uri":"spotify:track:48lxT5qJF0yYyf2z4wB4xW","trackType":"spotify","codec":"ogg","seek":0,"duration":144,"samplerate":"320 kbps","bitdepth":"16 bit","random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":true,"stream":"spotify","updatedb":false,"volatile":false,"service":"spop"} May 11 14:11:01 volumio volumio[1849]: SPOTIFY: PUSH STATE SPOTIFY May 11 14:11:01 volumio volumio[1849]: SPOTIFY: {"status":"pause","service":"spop","title":"Mr. Mellow (Always Remember Us This Way)","artist":"Mr. Mellow","album":"Mr. Mellow (Always Remember Us This Way)","albumart":"https://i.scdn.co/image/ab67616d00001e02c1a8fbc85fc4417cff99c9a0","uri":"spotify:track:4FKDsKzzA0UhvAvoQm7EgT","trackType":"spotify","seek":97593,"duration":146,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 11 14:11:01 volumio volumio[1849]: info: CoreCommandRouter::servicePushState May 11 14:11:01 volumio volumio[1849]: info: CoreStateMachine::pushState May 11 14:11:01 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 14:11:01 volumio volumio[1849]: info: CoreCommandRouter::volumioPushState May 11 14:11:01 volumio volumio[1849]: info: [ASDebug] CurState: pause PrevState: stop May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=debug msg="resume track at 97461ms" May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=debug msg="fetched chunk 9/12, size: 524288" uri="spotify:track:4FKDsKzzA0UhvAvoQm7EgT" May 11 14:11:01 volumio volumio[1849]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 May 11 14:11:01 volumio volumio[1849]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 May 11 14:11:01 volumio volumio[1849]: info: FusionDsp - ---- read samplerate from file: 44100 May 11 14:11:01 volumio volumio[1849]: info: FusionDsp - If filter freq >samplerate/2 then disable it May 11 14:11:01 volumio volumio[1849]: info: FusionDsp - {"Reload":{"result":"Ok"}} May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=trace msg="scheduling prefetch in 18s" May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=debug msg="sending successful reply for dealer request" May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 14:11:01 volumio go-librespot[2019]: time="2025-05-11T14:11:01+02:00" level=trace msg="emitting websocket event: playing" May 11 14:11:01 volumio volumio[1849]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4FKDsKzzA0UhvAvoQm7EgT","play_origin":"com.spotify.service.carplayv2"}} May 11 14:11:01 volumio volumio[1849]: SPOTIFY: PUSH STATE SPOTIFY May 11 14:11:01 volumio volumio[1849]: SPOTIFY: {"status":"play","service":"spop","title":"Mr. Mellow (Always Remember Us This Way)","artist":"Mr. Mellow","album":"Mr. Mellow (Always Remember Us This Way)","albumart":"https://i.scdn.co/image/ab67616d00001e02c1a8fbc85fc4417cff99c9a0","uri":"spotify:track:4FKDsKzzA0UhvAvoQm7EgT","trackType":"spotify","seek":97593,"duration":146,"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 11 14:11:01 volumio volumio[1849]: info: CoreCommandRouter::servicePushState May 11 14:11:01 volumio volumio[1849]: info: CoreStateMachine::pushState May 11 14:11:01 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 14:11:01 volumio volumio[1849]: info: CoreCommandRouter::volumioPushState May 11 14:11:01 volumio volumio[1849]: info: [ASDebug] CurState: play PrevState: stop May 11 14:11:01 volumio volumio[1849]: info: [ASDebug] Togle GPIO: ON May 11 14:11:01 volumio volumio[1849]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 May 11 14:11:01 volumio volumio[1849]: SPOTIFY: PUSH STATE SPOTIFY May 11 14:11:01 volumio volumio[1849]: SPOTIFY: {"status":"play","service":"spop","title":"Mr. Mellow (Always Remember Us This Way)","artist":"Mr. Mellow","album":"Mr. Mellow (Always Remember Us This Way)","albumart":"https://i.scdn.co/image/ab67616d00001e02c1a8fbc85fc4417cff99c9a0","uri":"spotify:track:4FKDsKzzA0UhvAvoQm7EgT","trackType":"spotify","seek":97593,"duration":146,"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 11 14:11:01 volumio volumio[1849]: info: CoreCommandRouter::servicePushState May 11 14:11:01 volumio volumio[1849]: info: CoreStateMachine::pushState May 11 14:11:01 volumio volumio[1849]: info: CoreCommandRouter::volumioPushState May 11 14:11:01 volumio volumio[1849]: info: [ASDebug] CurState: play PrevState: play May 11 14:11:01 volumio volumio[1849]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 May 11 14:11:02 volumio volumio[1849]: SPOTIFY: SETTING SPOTIFY VOLUME 0 May 11 14:11:02 volumio volumio[1849]: info: Sending Spotify command with payload to local API: /player/volume May 11 14:11:02 volumio go-librespot[2019]: time="2025-05-11T14:11:02+02:00" level=debug msg="update volume to 0/65535" May 11 14:11:03 volumio go-librespot[2019]: time="2025-05-11T14:11:03+02:00" level=debug msg="put connect state because VOLUME_CHANGED" May 11 14:11:03 volumio go-librespot[2019]: time="2025-05-11T14:11:03+02:00" level=trace msg="emitting websocket event: volume" May 11 14:11:03 volumio volumio[1849]: SPOTIFY: received: {"type":"volume","data":{"value":0,"max":100}} May 11 14:11:03 volumio volumio[1849]: SPOTIFY: RECEIVED SPOTIFY VOLUME 0 May 11 14:11:08 volumio go-librespot[2019]: time="2025-05-11T14:11:08+02:00" level=debug msg="fetched chunk 12/12, size: 184573" uri="spotify:track:4FKDsKzzA0UhvAvoQm7EgT" May 11 14:11:09 volumio go-librespot[2019]: time="2025-05-11T14:11:09+02:00" level=debug msg="handling skip_next player command from b646b1402e3e1d7c0767f15c2f7949604c73f8a8" May 11 14:11:09 volumio go-librespot[2019]: time="2025-05-11T14:11:09+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6W7bZAKfF7NItMbQwEH9mI" May 11 14:11:09 volumio go-librespot[2019]: time="2025-05-11T14:11:09+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 14:11:09 volumio go-librespot[2019]: time="2025-05-11T14:11:09+02:00" level=trace msg="emitting websocket event: will_play" May 11 14:11:09 volumio volumio[1849]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6W7bZAKfF7NItMbQwEH9mI","play_origin":"com.spotify.service.carplayv2"}} May 11 14:11:09 volumio go-librespot[2019]: time="2025-05-11T14:11:09+02:00" level=debug msg="selected format OGG_VORBIS_320 (7c8c9e3631e1770558cf9505e0e8a208031ff69a)" uri="spotify:track:6W7bZAKfF7NItMbQwEH9mI" May 11 14:11:09 volumio go-librespot[2019]: time="2025-05-11T14:11:09+02:00" level=debug msg="requested aes key for file 7c8c9e3631e1770558cf9505e0e8a208031ff69a, gid: 6W7bZAKfF7NItMbQwEH9mI" May 11 14:11:09 volumio go-librespot[2019]: time="2025-05-11T14:11:09+02:00" level=debug msg="fetched first chunk of 11, total size is 5595300 bytes" uri="spotify:track:6W7bZAKfF7NItMbQwEH9mI" May 11 14:11:09 volumio go-librespot[2019]: time="2025-05-11T14:11:09+02:00" level=info msg="loaded track \"Dancing All Alone - BOVSKI Remix\" (paused: false, position: 0ms, duration: 132000ms, prefetched: false)" uri="spotify:track:6W7bZAKfF7NItMbQwEH9mI" May 11 14:11:09 volumio go-librespot[2019]: time="2025-05-11T14:11:09+02:00" level=debug msg="fetched chunk 1/10, size: 524288" uri="spotify:track:6W7bZAKfF7NItMbQwEH9mI" May 11 14:11:09 volumio go-librespot[2019]: time="2025-05-11T14:11:09+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 14:11:09 volumio go-librespot[2019]: time="2025-05-11T14:11:09+02:00" level=trace msg="scheduling prefetch in 102s" May 11 14:11:09 volumio go-librespot[2019]: time="2025-05-11T14:11:09+02:00" level=trace msg="emitting websocket event: metadata" May 11 14:11:09 volumio go-librespot[2019]: time="2025-05-11T14:11:09+02:00" level=debug msg="sending successful reply for dealer request" May 11 14:11:09 volumio volumio[1849]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6W7bZAKfF7NItMbQwEH9mI","name":"Dancing All Alone - BOVSKI Remix","artist_names":["EMMY","BOVSKI"],"album_name":"Dancing All Alone (BOVSKI Remix)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02cb60e7908cf6b12aac1fe16d","position":0,"duration":132000,"release_date":"year:2024 month:7 day:3","track_number":1,"disc_number":1}} May 11 14:11:09 volumio go-librespot[2019]: time="2025-05-11T14:11:09+02:00" level=debug msg="fetched chunk 2/10, size: 524288" uri="spotify:track:6W7bZAKfF7NItMbQwEH9mI" May 11 14:11:09 volumio go-librespot[2019]: time="2025-05-11T14:11:09+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 14:11:09 volumio go-librespot[2019]: time="2025-05-11T14:11:09+02:00" level=trace msg="emitting websocket event: playing" May 11 14:11:09 volumio volumio[1849]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6W7bZAKfF7NItMbQwEH9mI","play_origin":"com.spotify.service.carplayv2"}} May 11 14:11:09 volumio volumio[1849]: SPOTIFY: PUSH STATE SPOTIFY May 11 14:11:09 volumio volumio[1849]: SPOTIFY: {"status":"play","service":"spop","title":"Dancing All Alone - BOVSKI Remix","artist":"EMMY, BOVSKI","album":"Dancing All Alone (BOVSKI Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e02cb60e7908cf6b12aac1fe16d","uri":"spotify:track:6W7bZAKfF7NItMbQwEH9mI","trackType":"spotify","seek":0,"duration":132,"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 11 14:11:09 volumio volumio[1849]: info: CoreCommandRouter::servicePushState May 11 14:11:09 volumio volumio[1849]: info: CoreStateMachine::pushState May 11 14:11:09 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 14:11:09 volumio volumio[1849]: info: CoreCommandRouter::volumioPushState May 11 14:11:09 volumio volumio[1849]: info: [ASDebug] CurState: play PrevState: play May 11 14:11:09 volumio volumio[1849]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 May 11 14:11:09 volumio go-librespot[2019]: time="2025-05-11T14:11:09+02:00" level=debug msg="fetched chunk 3/10, size: 524288" uri="spotify:track:6W7bZAKfF7NItMbQwEH9mI" May 11 14:11:10 volumio volumio[1849]: SPOTIFY: PUSH STATE SPOTIFY May 11 14:11:10 volumio volumio[1849]: SPOTIFY: {"status":"play","service":"spop","title":"Dancing All Alone - BOVSKI Remix","artist":"EMMY, BOVSKI","album":"Dancing All Alone (BOVSKI Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e02cb60e7908cf6b12aac1fe16d","uri":"spotify:track:6W7bZAKfF7NItMbQwEH9mI","trackType":"spotify","seek":0,"duration":132,"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 11 14:11:10 volumio volumio[1849]: info: CoreCommandRouter::servicePushState May 11 14:11:10 volumio volumio[1849]: info: CoreStateMachine::pushState May 11 14:11:10 volumio volumio[1849]: info: CoreCommandRouter::volumioPushState May 11 14:11:10 volumio volumio[1849]: info: [ASDebug] CurState: play PrevState: play May 11 14:11:10 volumio volumio[1849]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 May 11 14:11:14 volumio volumio[1849]: verbose: New Socket.io Connection to 192.168.9.177 from 192.168.9.176 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_4_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) CriOS/135.0.7049.83 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 7 May 11 14:11:14 volumio volumio[1849]: info: Received Get System Info May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 11 14:11:14 volumio volumio[1849]: info: Discovery: Getting this device information May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::volumioGetState May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::volumioGetState May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::volumioGetVisibleSources May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::volumioGetState May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::volumioGetQueue May 11 14:11:14 volumio volumio[1849]: info: CoreStateMachine::getQueue May 11 14:11:14 volumio volumio[1849]: info: CorePlayQueue::getQueue May 11 14:11:14 volumio volumio[1849]: info: Listing playlists May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 11 14:11:14 volumio volumio[1849]: info: Received Get System Info May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 11 14:11:14 volumio volumio[1849]: info: Discovery: Getting this device information May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::volumioGetState May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::volumioGetState May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::getUIConfigOnPlugin May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::getUIConfigOnPlugin May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::getUIConfigOnPlugin May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::getUIConfigOnPlugin May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::getUIConfigOnPlugin May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::getUIConfigOnPlugin May 11 14:11:14 volumio volumio[1849]: info: FusionDsp - Choose a preset May 11 14:11:14 volumio volumio[1849]: info: FusionDsp - Choose a preset May 11 14:11:14 volumio volumio[1849]: info: FusionDsp - Choose a preset May 11 14:11:14 volumio volumio[1849]: info: FusionDsp - Choose a preset May 11 14:11:14 volumio volumio[1849]: info: FusionDsp - Choose a preset May 11 14:11:14 volumio volumio[1849]: info: FusionDsp - Choose a preset May 11 14:11:14 volumio volumio[1849]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json May 11 14:11:14 volumio volumio[1849]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json May 11 14:11:14 volumio volumio[1849]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json May 11 14:11:14 volumio volumio[1849]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json May 11 14:11:14 volumio volumio[1849]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json May 11 14:11:14 volumio volumio[1849]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json May 11 14:11:14 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 11 14:11:20 volumio volumio[1849]: info: VolumeController::SetAlsaVolume43 May 11 14:11:20 volumio volumio[1849]: info: CoreStateMachine::pushState May 11 14:11:20 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 14:11:20 volumio volumio[1849]: info: CoreCommandRouter::volumioPushState May 11 14:11:20 volumio volumio[1849]: info: [ASDebug] CurState: play PrevState: play May 11 14:11:20 volumio volumio[1849]: SPOTIFY: RECEIVED VOLUMIO VOLUME 43 May 11 14:11:20 volumio volumio[1849]: SPOTIFY: SPOTIFY VOLUME 0 May 11 14:11:20 volumio volumio[1849]: SPOTIFY: VOLUMIO VOLUME 43 May 11 14:11:20 volumio volumio[1849]: SPOTIFY: DELTA VOLUME ENOUGH: true May 11 14:11:20 volumio volumio[1849]: info: Setting Spotify Volume from Volumio: 43 May 11 14:11:20 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:11:20 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:11:20 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000022] -121 May 11 14:11:20 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:11:20 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at snd_soc_component_update_bits on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:11:20 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:11:20 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at snd_soc_component_update_bits on i-sabre-codec-i2c.1-0048 for register: [0x00000020] -121 May 11 14:11:20 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000020] -121 May 11 14:11:20 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:11:20 volumio volumio[1849]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: amixer: Invalid command! May 11 14:11:21 volumio volumio[1849]: info: VolumeController::SetAlsaVolume100 May 11 14:11:21 volumio volumio[1849]: info: CoreStateMachine::pushState May 11 14:11:21 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 14:11:21 volumio volumio[1849]: info: CoreCommandRouter::volumioPushState May 11 14:11:21 volumio volumio[1849]: info: [ASDebug] CurState: play PrevState: play May 11 14:11:21 volumio volumio[1849]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 11 14:11:21 volumio volumio[1849]: SPOTIFY: SPOTIFY VOLUME 43 May 11 14:11:21 volumio volumio[1849]: SPOTIFY: VOLUMIO VOLUME 100 May 11 14:11:21 volumio volumio[1849]: SPOTIFY: DELTA VOLUME ENOUGH: true May 11 14:11:21 volumio volumio[1849]: info: Setting Spotify Volume from Volumio: 100 May 11 14:11:21 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:11:21 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000020] -121 May 11 14:11:21 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:11:21 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000022] -121 May 11 14:11:21 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000020] -121 May 11 14:11:21 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at snd_soc_component_update_bits on i-sabre-codec-i2c.1-0048 for register: [0x00000020] -121 May 11 14:11:21 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000020] -121 May 11 14:11:21 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:11:21 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000020] -121 May 11 14:11:21 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at snd_soc_component_update_bits on i-sabre-codec-i2c.1-0048 for register: [0x00000020] -121 May 11 14:11:21 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000020] -121 May 11 14:11:21 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:11:21 volumio volumio[1849]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: amixer: Invalid command! May 11 14:11:22 volumio go-librespot[2019]: time="2025-05-11T14:11:22+02:00" level=debug msg="fetched chunk 4/10, size: 524288" uri="spotify:track:6W7bZAKfF7NItMbQwEH9mI" May 11 14:11:22 volumio volumio[1849]: SPOTIFY: SETTING SPOTIFY VOLUME 100 May 11 14:11:22 volumio volumio[1849]: info: Sending Spotify command with payload to local API: /player/volume May 11 14:11:22 volumio go-librespot[2019]: time="2025-05-11T14:11:22+02:00" level=debug msg="update volume to 65535/65535" May 11 14:11:24 volumio go-librespot[2019]: time="2025-05-11T14:11:24+02:00" level=debug msg="put connect state because VOLUME_CHANGED" May 11 14:11:24 volumio go-librespot[2019]: time="2025-05-11T14:11:24+02:00" level=trace msg="emitting websocket event: volume" May 11 14:11:24 volumio volumio[1849]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} May 11 14:11:24 volumio volumio[1849]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 May 11 14:11:26 volumio volumio[1849]: info: CoreCommandRouter::getUIConfigOnPlugin May 11 14:11:26 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 11 14:11:26 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 11 14:11:26 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 11 14:11:26 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs May 11 14:11:26 volumio volumio[1849]: info: Received Get System Version May 11 14:11:26 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 11 14:11:29 volumio go-librespot[2019]: time="2025-05-11T14:11:29+02:00" level=trace msg="sent dealer ping" May 11 14:11:29 volumio go-librespot[2019]: time="2025-05-11T14:11:29+02:00" level=trace msg="received dealer pong" May 11 14:11:30 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 11 14:11:30 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 11 14:11:31 volumio volumio[1849]: info: CoreCommandRouter::getUIConfigOnPlugin May 11 14:11:31 volumio volumio[1849]: info: FusionDsp - Choose a preset May 11 14:11:31 volumio volumio[1849]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json May 11 14:11:31 volumio volumio[1849]: info: CoreCommandRouter::getUIConfigOnPlugin May 11 14:11:31 volumio volumio[1849]: info: CoreCommandRouter::getUIConfigOnPlugin May 11 14:11:31 volumio volumio[1849]: info: FusionDsp - Choose a preset May 11 14:11:31 volumio volumio[1849]: info: FusionDsp - Choose a preset May 11 14:11:31 volumio volumio[1849]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json May 11 14:11:31 volumio volumio[1849]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json May 11 14:11:35 volumio go-librespot[2019]: time="2025-05-11T14:11:35+02:00" level=debug msg="fetched chunk 5/10, size: 524288" uri="spotify:track:6W7bZAKfF7NItMbQwEH9mI" May 11 14:11:37 volumio volumio[1849]: info: Starting Uninstall of plugin system_controller - ampswitch May 11 14:11:37 volumio volumio[1849]: info: Uninstalling plugin ampswitch May 11 14:11:37 volumio volumio[1849]: info: [ASDebug] Port: 24 May 11 14:11:37 volumio volumio[1849]: info: [ASDebug] Inverted: false May 11 14:11:37 volumio volumio[1849]: info: [ASDebug] Delay: 720 May 11 14:11:47 volumio go-librespot[2019]: time="2025-05-11T14:11:47+02:00" level=debug msg="fetched chunk 6/10, size: 524288" uri="spotify:track:6W7bZAKfF7NItMbQwEH9mI" May 11 14:11:50 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 11 14:11:50 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 11 14:11:50 volumio volumio[1849]: info: CoreCommandRouter::getUIConfigOnPlugin May 11 14:11:50 volumio volumio[1849]: info: CoreCommandRouter::getUIConfigOnPlugin May 11 14:11:50 volumio volumio[1849]: info: FusionDsp - Choose a preset May 11 14:11:50 volumio volumio[1849]: info: FusionDsp - Choose a preset May 11 14:11:50 volumio volumio[1849]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json May 11 14:11:50 volumio volumio[1849]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json May 11 14:11:53 volumio volumio[1849]: info: CoreCommandRouter::getUIConfigOnPlugin May 11 14:11:53 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 11 14:11:53 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 11 14:11:53 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 11 14:11:53 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs May 11 14:11:53 volumio volumio[1849]: info: Received Get System Version May 11 14:11:53 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 11 14:11:59 volumio go-librespot[2019]: time="2025-05-11T14:11:59+02:00" level=trace msg="sent dealer ping" May 11 14:11:59 volumio go-librespot[2019]: time="2025-05-11T14:11:59+02:00" level=trace msg="received dealer pong" May 11 14:11:59 volumio go-librespot[2019]: time="2025-05-11T14:11:59+02:00" level=debug msg="fetched chunk 7/10, size: 524288" uri="spotify:track:6W7bZAKfF7NItMbQwEH9mI" May 11 14:12:07 volumio volumio[1849]: info: CoreCommandRouter::getUIConfigOnPlugin May 11 14:12:07 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions May 11 14:12:07 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 14:12:07 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 11 14:12:07 volumio volumio[1849]: info: Getting Alsa Cards List without I2S DAC May 11 14:12:07 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SNumber May 11 14:12:07 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 14:12:07 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 14:12:07 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 14:12:07 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 14:12:07 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 14:12:07 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 14:12:07 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 14:12:07 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 14:12:07 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode May 11 14:12:07 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:12:07 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000020] -121 May 11 14:12:07 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:12:07 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000022] -121 May 11 14:12:07 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000022] -121 May 11 14:12:07 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus May 11 14:12:11 volumio volumio[1849]: info: CALLMETHOD: audio_interface alsa_controller saveAlsaOptions [object Object] May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveAlsaOptions May 11 14:12:11 volumio volumio[1849]: info: Preparing to save Alsa Options, stopping services first May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::volumioGetState May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::volumioPause May 11 14:12:11 volumio volumio[1849]: info: CoreStateMachine::pause May 11 14:12:11 volumio volumio[1849]: info: CoreStateMachine::stPlaybackTimer May 11 14:12:11 volumio volumio[1849]: info: CoreStateMachine::servicePause May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::servicePause May 11 14:12:11 volumio volumio[1849]: info: Spotify Received pause May 11 14:12:11 volumio volumio[1849]: SPOTIFY: SPOTIFY PAUSE May 11 14:12:11 volumio volumio[1849]: SPOTIFY: {"status":"play","title":"Dancing All Alone - BOVSKI Remix","artist":"EMMY, BOVSKI","album":"Dancing All Alone (BOVSKI Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e02cb60e7908cf6b12aac1fe16d","uri":"spotify:track:6W7bZAKfF7NItMbQwEH9mI","trackType":"spotify","codec":"ogg","seek":11000,"duration":132,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":100,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true,"service":"spop"} May 11 14:12:11 volumio volumio[1849]: info: Sending Spotify command to local API: /player/pause May 11 14:12:11 volumio volumio[1849]: info: Saving Audio Output to: {"output_device":{"value":"0","label":"I-Sabre Q2M DAC"},"i2s":true,"i2sid":{"value":"i-sabre-q2m","label":"Audiophonics I-Sabre ES9028Q2M"}} May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SNumber May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SAlsaName May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SMixer May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: Found match in i2s Card Database: setting mixer Digital for card Audiophonics I-Sabre ES9028Q2M May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::volumioUpdateVolumeSettings May 11 14:12:11 volumio volumio[1849]: info: Updating Volume Controller Parameters: Device: 0 Name: Audiophonics I-Sabre ES9028Q2M Mixer: Digital Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume May 11 14:12:11 volumio volumio[1849]: info: Disabling external Volume Control May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::getUIConfigOnPlugin May 11 14:12:11 volumio volumio[1849]: info: Preparing to generate the ALSA configuration file May 11 14:12:11 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:12:11 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000020] -121 May 11 14:12:11 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:12:11 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000022] -121 May 11 14:12:11 volumio volumio[1849]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf May 11 14:12:11 volumio volumio[1849]: info: Reading ALSA contributions from plugins. May 11 14:12:11 volumio go-librespot[2019]: time="2025-05-11T14:12:11+02:00" level=debug msg="pause track at 62053ms" May 11 14:12:11 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:12:11 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000020] -121 May 11 14:12:11 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:12:11 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000022] -121 May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 11 14:12:11 volumio volumio[1849]: info: Getting Alsa Cards List without I2S DAC May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SNumber May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 14:12:11 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:12:11 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000020] -121 May 11 14:12:11 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:12:11 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000022] -121 May 11 14:12:11 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000022] -121 May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus May 11 14:12:11 volumio volumio[1849]: info: VolumeController:: Volume=76 Mute =true May 11 14:12:11 volumio volumio[1849]: info: CoreStateMachine::pushState May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::volumioPushState May 11 14:12:11 volumio volumio[1849]: info: [ASDebug] CurState: play PrevState: play May 11 14:12:11 volumio volumio[1849]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 May 11 14:12:11 volumio volumio[1849]: SPOTIFY: SPOTIFY VOLUME 100 May 11 14:12:11 volumio volumio[1849]: SPOTIFY: VOLUMIO VOLUME 0 May 11 14:12:11 volumio volumio[1849]: SPOTIFY: DELTA VOLUME ENOUGH: true May 11 14:12:11 volumio volumio[1849]: info: Setting Spotify Volume from Volumio: 0 May 11 14:12:11 volumio volumio[1849]: info: Asound.conf file unchanged, so no further update is needed May 11 14:12:11 volumio volumio[1849]: info: Output device has changed, restarting MPD May 11 14:12:11 volumio sudo[2635]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 11 14:12:11 volumio sudo[2635]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 14:12:11 volumio sudo[2635]: pam_unix(sudo:session): session closed for user root May 11 14:12:11 volumio volumio[1849]: info: Output device has changed, restarting Shairport Sync May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 14:12:11 volumio sudo[2638]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 11 14:12:11 volumio sudo[2638]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 14:12:11 volumio systemd[1]: Stopping Music Player Daemon... May 11 14:12:11 volumio volumio[1849]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 11 14:12:11 volumio systemd[1]: mpd.service: Succeeded. May 11 14:12:11 volumio systemd[1]: Stopped Music Player Daemon. May 11 14:12:11 volumio volumio[1849]: info: MPD Permissions set May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 14:12:11 volumio volumio[1849]: info: Starting Shairport Sync May 11 14:12:11 volumio systemd[1]: Starting Music Player Daemon... May 11 14:12:11 volumio sudo[2649]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 11 14:12:11 volumio sudo[2649]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 14:12:11 volumio go-librespot[2019]: time="2025-05-11T14:12:11+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 14:12:11 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 11 14:12:11 volumio systemd[1]: shairport-sync.service: Succeeded. May 11 14:12:11 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 11 14:12:11 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 11 14:12:11 volumio sudo[2649]: pam_unix(sudo:session): session closed for user root May 11 14:12:11 volumio volumio[1849]: info: Shairport-Sync Started May 11 14:12:11 volumio sudo[2643]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 11 14:12:11 volumio sudo[2643]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 14:12:11 volumio sudo[2643]: pam_unix(sudo:session): session closed for user root May 11 14:12:11 volumio go-librespot[2019]: time="2025-05-11T14:12:11+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 14:12:11 volumio go-librespot[2019]: time="2025-05-11T14:12:11+02:00" level=trace msg="emitting websocket event: paused" May 11 14:12:11 volumio volumio[1849]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6W7bZAKfF7NItMbQwEH9mI","play_origin":"com.spotify.service.carplayv2"}} May 11 14:12:11 volumio volumio[1849]: SPOTIFY: PUSH STATE SPOTIFY May 11 14:12:11 volumio volumio[1849]: SPOTIFY: {"status":"pause","service":"spop","title":"Dancing All Alone - BOVSKI Remix","artist":"EMMY, BOVSKI","album":"Dancing All Alone (BOVSKI Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e02cb60e7908cf6b12aac1fe16d","uri":"spotify:track:6W7bZAKfF7NItMbQwEH9mI","trackType":"spotify","seek":62000,"duration":132,"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 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::servicePushState May 11 14:12:11 volumio volumio[1849]: info: CoreStateMachine::pushState May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 14:12:11 volumio volumio[1849]: info: CoreCommandRouter::volumioPushState May 11 14:12:11 volumio volumio[1849]: info: [ASDebug] CurState: pause PrevState: play May 11 14:12:11 volumio volumio[1849]: info: [ASDebug] InitTimeout - Amp off in: 720 ms May 11 14:12:11 volumio volumio[1849]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 May 11 14:12:11 volumio mpd[2655]: May 11 14:12 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 11 14:12:11 volumio systemd[1]: Started Music Player Daemon. May 11 14:12:11 volumio sudo[2638]: pam_unix(sudo:session): session closed for user root May 11 14:12:11 volumio volumio[1849]: error: updateQueue error: null May 11 14:12:12 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at snd_soc_component_update_bits on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:12:12 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at snd_soc_component_update_bits on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 May 11 14:12:12 volumio volumio[1849]: info: [ASDebug] Togle GPIO: OFF May 11 14:12:12 volumio volumio[1849]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 11 14:12:12 volumio volumio[1849]: Error: ESPIPE: invalid seek, write May 11 14:12:12 volumio volumio[1849]: at Object.writeSync (fs.js:711:3) May 11 14:12:12 volumio volumio[1849]: at Gpio.writeSync (/data/plugins/system_controller/ampswitch/node_modules/onoff/onoff.js:243:8) May 11 14:12:12 volumio volumio[1849]: at AmpSwitchController.off (/data/plugins/system_controller/ampswitch/index.js:221:23) May 11 14:12:12 volumio volumio[1849]: at Timeout._onTimeout (/data/plugins/system_controller/ampswitch/index.js:195:88) May 11 14:12:12 volumio volumio[1849]: at listOnTimeout (internal/timers.js:554:17) May 11 14:12:12 volumio volumio[1849]: at processTimers (internal/timers.js:497:7) { May 11 14:12:12 volumio volumio[1849]: errno: -29, May 11 14:12:12 volumio volumio[1849]: syscall: 'write', May 11 14:12:12 volumio volumio[1849]: code: 'ESPIPE' May 11 14:12:12 volumio volumio[1849]: } May 11 14:12:12 volumio volumio[1849]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 11 14:12:12 volumio sudo[2674]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-11 14:11 May 11 14:12:12 volumio sudo[2674]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="9ab87de061b3649c303da550e73c92d340b0f989" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 30 Apr 2025 11:47:57 AM CEST" VOLUMIO_VERSION="3.807" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fddd10196af80fdc784c726185a6abe4"