-- Logs begin at Fri 2025-12-12 02:47:33 JST, end at Tue 2025-12-30 11:24:56 JST. -- Dec 30 11:23:05 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:05+09:00" level=debug msg="fetched chunk 8/23, size: 524288" uri="spotify:track:4bqwzOzRpLgAkQMtxtRXq0" Dec 30 11:23:05 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:05+09:00" level=trace msg="received accesspoint ping" Dec 30 11:23:05 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:05+09:00" level=trace msg="received accesspoint pong ack" Dec 30 11:23:06 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:06+09:00" level=trace msg="sent dealer ping" Dec 30 11:23:06 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:06+09:00" level=trace msg="received dealer pong" Dec 30 11:23:10 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:10+09:00" level=debug msg="handling play player command from ae9fa72e7bdf601bfefe1272a12caf7caaed7321" Dec 30 11:23:10 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:10+09:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1EQnqst5TRi17F" Dec 30 11:23:10 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:10+09:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1EQnqst5TRi17F" Dec 30 11:23:10 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:10+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:65YmLoJJChUgcrVUZP9e6Y" Dec 30 11:23:11 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:11+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:23:11 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:11+09:00" level=trace msg="emitting websocket event: will_play" Dec 30 11:23:11 jbl-4312 volumio[3104]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1EQnqst5TRi17F","uri":"spotify:track:65YmLoJJChUgcrVUZP9e6Y","play_origin":"playlist/ondemand"}} Dec 30 11:23:11 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:11+09:00" level=debug msg="selected format OGG_VORBIS_320 (edcfad9fc54fd02be95d53db015dc842e57720cd)" uri="spotify:track:65YmLoJJChUgcrVUZP9e6Y" Dec 30 11:23:11 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:11+09:00" level=debug msg="requested aes key for file edcfad9fc54fd02be95d53db015dc842e57720cd, gid: 65YmLoJJChUgcrVUZP9e6Y" Dec 30 11:23:11 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:11+09:00" level=trace msg="found 3 cdn urls" uri="spotify:track:65YmLoJJChUgcrVUZP9e6Y" Dec 30 11:23:11 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:11+09:00" level=debug msg="fetched first chunk of 16, total size is 8353708 bytes" uri="spotify:track:65YmLoJJChUgcrVUZP9e6Y" Dec 30 11:23:11 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:11+09:00" level=info msg="loaded track \"Midnight Dreamin’\" (paused: false, position: 0ms, duration: 202453ms, prefetched: false)" uri="spotify:track:65YmLoJJChUgcrVUZP9e6Y" Dec 30 11:23:11 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:11+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:23:11 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:11+09:00" level=trace msg="scheduling prefetch in 172s" Dec 30 11:23:11 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:11+09:00" level=trace msg="emitting websocket event: metadata" Dec 30 11:23:11 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:11+09:00" level=debug msg="sending successful reply for dealer request" Dec 30 11:23:11 jbl-4312 volumio[3104]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:65YmLoJJChUgcrVUZP9e6Y","name":"Midnight Dreamin’","artist_names":["DJ HASEBE","SALU","SIRUP"],"album_name":"Wonderful tomorrow","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02058b30ddbaad2e72a771623c","position":0,"duration":202453,"release_date":"year:2020 month:9 day:14","track_number":10,"disc_number":1}} Dec 30 11:23:11 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:11+09:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:65YmLoJJChUgcrVUZP9e6Y" Dec 30 11:23:11 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:11+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:23:11 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:11+09:00" level=trace msg="emitting websocket event: playing" Dec 30 11:23:11 jbl-4312 volumio[3104]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:37i9dQZF1EQnqst5TRi17F","uri":"spotify:track:65YmLoJJChUgcrVUZP9e6Y","resume":false,"play_origin":"playlist/ondemand"}} Dec 30 11:23:11 jbl-4312 volumio[3104]: SPOTIFY: PUSH STATE SPOTIFY Dec 30 11:23:11 jbl-4312 volumio[3104]: SPOTIFY: {"status":"play","service":"spop","title":"Midnight Dreamin’","artist":"DJ HASEBE, SALU, SIRUP","album":"Wonderful tomorrow","albumart":"https://i.scdn.co/image/ab67616d00001e02058b30ddbaad2e72a771623c","uri":"spotify:track:65YmLoJJChUgcrVUZP9e6Y","trackType":"spotify","seek":0,"duration":202,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 30 11:23:11 jbl-4312 volumio[3104]: info: CoreCommandRouter::servicePushState Dec 30 11:23:11 jbl-4312 volumio[3104]: info: CoreStateMachine::pushState Dec 30 11:23:11 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 11:23:11 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioPushState Dec 30 11:23:11 jbl-4312 volumio[3104]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 30 11:23:11 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:11+09:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:65YmLoJJChUgcrVUZP9e6Y" Dec 30 11:23:11 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:11+09:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:65YmLoJJChUgcrVUZP9e6Y" Dec 30 11:23:11 jbl-4312 volumio[3104]: SPOTIFY: PUSH STATE SPOTIFY Dec 30 11:23:11 jbl-4312 volumio[3104]: SPOTIFY: {"status":"play","service":"spop","title":"Midnight Dreamin’","artist":"DJ HASEBE, SALU, SIRUP","album":"Wonderful tomorrow","albumart":"https://i.scdn.co/image/ab67616d00001e02058b30ddbaad2e72a771623c","uri":"spotify:track:65YmLoJJChUgcrVUZP9e6Y","trackType":"spotify","seek":0,"duration":202,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 30 11:23:11 jbl-4312 volumio[3104]: info: CoreCommandRouter::servicePushState Dec 30 11:23:11 jbl-4312 volumio[3104]: info: CoreStateMachine::pushState Dec 30 11:23:11 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioPushState Dec 30 11:23:11 jbl-4312 volumio[3104]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 30 11:23:25 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:25+09:00" level=debug msg="fetched chunk 4/15, size: 524288" uri="spotify:track:65YmLoJJChUgcrVUZP9e6Y" Dec 30 11:23:36 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:36+09:00" level=trace msg="sent dealer ping" Dec 30 11:23:36 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:36+09:00" level=trace msg="received dealer pong" Dec 30 11:23:36 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:36+09:00" level=debug msg="handling play player command from ae9fa72e7bdf601bfefe1272a12caf7caaed7321" Dec 30 11:23:36 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:36+09:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1EQnqst5TRi17F" Dec 30 11:23:36 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:36+09:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1EQnqst5TRi17F" Dec 30 11:23:36 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:36+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:440V0qKkY3t51v11Q0T1jt" Dec 30 11:23:36 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:36+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:23:36 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:36+09:00" level=trace msg="emitting websocket event: will_play" Dec 30 11:23:36 jbl-4312 volumio[3104]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1EQnqst5TRi17F","uri":"spotify:track:440V0qKkY3t51v11Q0T1jt","play_origin":"playlist/ondemand"}} Dec 30 11:23:36 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:36+09:00" level=debug msg="selected format OGG_VORBIS_320 (8b3e27adb7eeb328594cefbad416dab76c50f33a)" uri="spotify:track:440V0qKkY3t51v11Q0T1jt" Dec 30 11:23:36 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:36+09:00" level=debug msg="requested aes key for file 8b3e27adb7eeb328594cefbad416dab76c50f33a, gid: 440V0qKkY3t51v11Q0T1jt" Dec 30 11:23:36 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:36+09:00" level=trace msg="found 3 cdn urls" uri="spotify:track:440V0qKkY3t51v11Q0T1jt" Dec 30 11:23:37 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:37+09:00" level=debug msg="fetched first chunk of 22, total size is 11125300 bytes" uri="spotify:track:440V0qKkY3t51v11Q0T1jt" Dec 30 11:23:37 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:37+09:00" level=info msg="loaded track \"イツナロウバ\" (paused: false, position: 0ms, duration: 269466ms, prefetched: false)" uri="spotify:track:440V0qKkY3t51v11Q0T1jt" Dec 30 11:23:37 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:37+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:23:37 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:37+09:00" level=trace msg="scheduling prefetch in 239s" Dec 30 11:23:37 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:37+09:00" level=trace msg="emitting websocket event: metadata" Dec 30 11:23:37 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:37+09:00" level=debug msg="sending successful reply for dealer request" Dec 30 11:23:37 jbl-4312 volumio[3104]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:440V0qKkY3t51v11Q0T1jt","name":"イツナロウバ","artist_names":["KICK THE CAN CREW"],"album_name":"イツナロウバ","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02040d12dd3c38acfffcacabf0","position":0,"duration":269466,"release_date":"year:2001 month:7 day:11","track_number":1,"disc_number":1}} Dec 30 11:23:37 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:37+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:23:37 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:37+09:00" level=trace msg="emitting websocket event: playing" Dec 30 11:23:37 jbl-4312 volumio[3104]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:37i9dQZF1EQnqst5TRi17F","uri":"spotify:track:440V0qKkY3t51v11Q0T1jt","resume":false,"play_origin":"playlist/ondemand"}} Dec 30 11:23:37 jbl-4312 volumio[3104]: SPOTIFY: PUSH STATE SPOTIFY Dec 30 11:23:37 jbl-4312 volumio[3104]: SPOTIFY: {"status":"play","service":"spop","title":"イツナロウバ","artist":"KICK THE CAN CREW","album":"イツナロウバ","albumart":"https://i.scdn.co/image/ab67616d00001e02040d12dd3c38acfffcacabf0","uri":"spotify:track:440V0qKkY3t51v11Q0T1jt","trackType":"spotify","seek":0,"duration":269,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 30 11:23:37 jbl-4312 volumio[3104]: info: CoreCommandRouter::servicePushState Dec 30 11:23:37 jbl-4312 volumio[3104]: info: CoreStateMachine::pushState Dec 30 11:23:37 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 11:23:37 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioPushState Dec 30 11:23:37 jbl-4312 volumio[3104]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 30 11:23:37 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:37+09:00" level=debug msg="fetched chunk 3/21, size: 524288" uri="spotify:track:440V0qKkY3t51v11Q0T1jt" Dec 30 11:23:37 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:37+09:00" level=debug msg="fetched chunk 2/21, size: 524288" uri="spotify:track:440V0qKkY3t51v11Q0T1jt" Dec 30 11:23:37 jbl-4312 volumio[3104]: SPOTIFY: PUSH STATE SPOTIFY Dec 30 11:23:37 jbl-4312 volumio[3104]: SPOTIFY: {"status":"play","service":"spop","title":"イツナロウバ","artist":"KICK THE CAN CREW","album":"イツナロウバ","albumart":"https://i.scdn.co/image/ab67616d00001e02040d12dd3c38acfffcacabf0","uri":"spotify:track:440V0qKkY3t51v11Q0T1jt","trackType":"spotify","seek":0,"duration":269,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 30 11:23:37 jbl-4312 volumio[3104]: info: CoreCommandRouter::servicePushState Dec 30 11:23:37 jbl-4312 volumio[3104]: info: CoreStateMachine::pushState Dec 30 11:23:37 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioPushState Dec 30 11:23:37 jbl-4312 volumio[3104]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 30 11:23:37 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:37+09:00" level=debug msg="fetched chunk 1/21, size: 524288" uri="spotify:track:440V0qKkY3t51v11Q0T1jt" Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=debug msg="handling play player command from ae9fa72e7bdf601bfefe1272a12caf7caaed7321" Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1EQnqst5TRi17F" Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1EQnqst5TRi17F" Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:32bpgwGYMZKGu8PnPkL1bN" Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=trace msg="emitting websocket event: will_play" Dec 30 11:23:39 jbl-4312 volumio[3104]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1EQnqst5TRi17F","uri":"spotify:track:32bpgwGYMZKGu8PnPkL1bN","play_origin":"playlist/ondemand"}} Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=debug msg="selected format OGG_VORBIS_320 (1aaedfd28895772362662376fd36229f2d407ec0)" uri="spotify:track:32bpgwGYMZKGu8PnPkL1bN" Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=debug msg="requested aes key for file 1aaedfd28895772362662376fd36229f2d407ec0, gid: 32bpgwGYMZKGu8PnPkL1bN" Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=trace msg="found 3 cdn urls" uri="spotify:track:32bpgwGYMZKGu8PnPkL1bN" Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=debug msg="fetched first chunk of 9, total size is 4440160 bytes" uri="spotify:track:32bpgwGYMZKGu8PnPkL1bN" Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=info msg="loaded track \"Secure '' Outro ''\" (paused: false, position: 0ms, duration: 106071ms, prefetched: false)" uri="spotify:track:32bpgwGYMZKGu8PnPkL1bN" Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=trace msg="scheduling prefetch in 76s" Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=trace msg="emitting websocket event: metadata" Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=debug msg="sending successful reply for dealer request" Dec 30 11:23:39 jbl-4312 volumio[3104]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:32bpgwGYMZKGu8PnPkL1bN","name":"Secure '' Outro ''","artist_names":["Daichi Yamamoto"],"album_name":"Secure '' Outro ''","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0247455ae4f36aa56309753eaa","position":0,"duration":106071,"release_date":"year:2025 month:12 day:14","track_number":1,"disc_number":1}} Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=debug msg="fetched chunk 3/8, size: 524288" uri="spotify:track:32bpgwGYMZKGu8PnPkL1bN" Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=debug msg="fetched chunk 1/8, size: 524288" uri="spotify:track:32bpgwGYMZKGu8PnPkL1bN" Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=trace msg="emitting websocket event: playing" Dec 30 11:23:39 jbl-4312 volumio[3104]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:37i9dQZF1EQnqst5TRi17F","uri":"spotify:track:32bpgwGYMZKGu8PnPkL1bN","resume":false,"play_origin":"playlist/ondemand"}} Dec 30 11:23:39 jbl-4312 volumio[3104]: SPOTIFY: PUSH STATE SPOTIFY Dec 30 11:23:39 jbl-4312 volumio[3104]: SPOTIFY: {"status":"play","service":"spop","title":"Secure '' Outro ''","artist":"Daichi Yamamoto","album":"Secure '' Outro ''","albumart":"https://i.scdn.co/image/ab67616d00001e0247455ae4f36aa56309753eaa","uri":"spotify:track:32bpgwGYMZKGu8PnPkL1bN","trackType":"spotify","seek":0,"duration":106,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 30 11:23:39 jbl-4312 volumio[3104]: info: CoreCommandRouter::servicePushState Dec 30 11:23:39 jbl-4312 volumio[3104]: info: CoreStateMachine::pushState Dec 30 11:23:39 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 11:23:39 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioPushState Dec 30 11:23:39 jbl-4312 volumio[3104]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 30 11:23:39 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:39+09:00" level=debug msg="fetched chunk 2/8, size: 524288" uri="spotify:track:32bpgwGYMZKGu8PnPkL1bN" Dec 30 11:23:39 jbl-4312 volumio[3104]: SPOTIFY: PUSH STATE SPOTIFY Dec 30 11:23:39 jbl-4312 volumio[3104]: SPOTIFY: {"status":"play","service":"spop","title":"Secure '' Outro ''","artist":"Daichi Yamamoto","album":"Secure '' Outro ''","albumart":"https://i.scdn.co/image/ab67616d00001e0247455ae4f36aa56309753eaa","uri":"spotify:track:32bpgwGYMZKGu8PnPkL1bN","trackType":"spotify","seek":0,"duration":106,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 30 11:23:39 jbl-4312 volumio[3104]: info: CoreCommandRouter::servicePushState Dec 30 11:23:39 jbl-4312 volumio[3104]: info: CoreStateMachine::pushState Dec 30 11:23:39 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioPushState Dec 30 11:23:39 jbl-4312 volumio[3104]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 30 11:23:41 jbl-4312 volumiologrotate[2829]: ls: cannot access '/var/log/samba/log.wb-JBL': No such file or directory Dec 30 11:23:41 jbl-4312 volumiologrotate[2829]: ls: cannot access '4312': No such file or directory Dec 30 11:23:51 jbl-4312 go-librespot[3621]: time="2025-12-30T11:23:51+09:00" level=debug msg="fetched chunk 4/8, size: 524288" uri="spotify:track:32bpgwGYMZKGu8PnPkL1bN" Dec 30 11:23:51 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:23:51.210+09:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.3.13:51485 Dec 30 11:23:51 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:23:51.238+09:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.3.13:51485 @ 0x20f87e0" latency=127.49527ms timeout=10s Dec 30 11:23:51 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:23:51.239+09:00 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="192.168.3.13:51485 @ 0x20f87e0" latency=129.091187ms platform=PLATFORM_IOS version=4.251222.0 Dec 30 11:23:51 jbl-4312 volumio[3104]: info: Received Get System Info Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 30 11:23:51 jbl-4312 volumio[3104]: info: Discovery: Getting this device information Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioGetState Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 30 11:23:51 jbl-4312 volumio[3104]: amixer -c 1 info | grep "Comtrue-inc UAC2 Device" Dec 30 11:23:51 jbl-4312 volumio[3104]: Card hw:1 'Device'/'Comtrue-inc Comtrue-inc UAC2 Device at usb-xhci-hcd.0.auto-1.4.3, high speed' Dec 30 11:23:51 jbl-4312 volumio[3104]: amixer -c 5 info | grep "SMSL USB AUDIO" Dec 30 11:23:51 jbl-4312 volumio[3104]: Card hw:5 'AUDIO'/'SMSL SMSL USB AUDIO at usb-xhci-hcd.0.auto-1.4.2, high speed' Dec 30 11:23:51 jbl-4312 volumio[3104]: amixer -c 5 info | grep "SMSL USB AUDIO" Dec 30 11:23:51 jbl-4312 volumio[3104]: Card hw:5 'AUDIO'/'SMSL SMSL USB AUDIO at usb-xhci-hcd.0.auto-1.4.2, high speed' Dec 30 11:23:51 jbl-4312 volumio[3104]: info: Received Get System Info Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 30 11:23:51 jbl-4312 volumio[3104]: info: Discovery: Getting this device information Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioGetState Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 30 11:23:51 jbl-4312 volumio[3104]: info: Discovery: Getting this device information Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioGetState Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 30 11:23:51 jbl-4312 volumio[3104]: verbose: New Socket.io Connection to 192.168.3.4:3000 from 192.168.3.13 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Dec 30 11:23:51 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Dec 30 11:23:52 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioGetState Dec 30 11:23:54 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:23:54.600+09:00 level=INFO msg="continue navigation request" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.3.13:51485 @ 0x20f87e0" latency=117.261152ms timeout=10s from=APP_PAGE_ROOT Dec 30 11:23:55 jbl-4312 sudo[31256]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 11:23:55 jbl-4312 sudo[31256]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 30 11:23:55 jbl-4312 sudo[31256]: pam_unix(sudo:session): session closed for user root Dec 30 11:23:55 jbl-4312 sudo[31258]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 11:23:55 jbl-4312 sudo[31258]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 30 11:23:55 jbl-4312 sudo[31258]: pam_unix(sudo:session): session closed for user root Dec 30 11:23:55 jbl-4312 volumio[3104]: verbose: New Socket.io Connection to 192.168.3.4 from 192.168.3.13 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 7 Dec 30 11:23:55 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 30 11:23:55 jbl-4312 sudo[31264]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 11:23:55 jbl-4312 sudo[31264]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 30 11:23:55 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 30 11:23:55 jbl-4312 sudo[31264]: pam_unix(sudo:session): session closed for user root Dec 30 11:23:55 jbl-4312 sudo[31266]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 11:23:55 jbl-4312 sudo[31266]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 30 11:23:55 jbl-4312 sudo[31266]: pam_unix(sudo:session): session closed for user root Dec 30 11:23:55 jbl-4312 volumio[3104]: verbose: New Socket.io Connection to 192.168.3.4 from 192.168.3.13 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 8 Dec 30 11:23:55 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 30 11:23:55 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioGetVisibleSources Dec 30 11:23:55 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:23:55 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioGetState Dec 30 11:23:55 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 30 11:23:55 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 30 11:23:55 jbl-4312 volumio[3104]: info: Received Get System Info Dec 30 11:23:55 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 30 11:23:55 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 30 11:23:55 jbl-4312 volumio[3104]: info: Discovery: Getting this device information Dec 30 11:23:55 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioGetState Dec 30 11:23:55 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 30 11:23:55 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioGetState Dec 30 11:23:55 jbl-4312 volumio[3104]: info: Listing playlists Dec 30 11:23:55 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 30 11:23:55 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 30 11:23:55 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 30 11:23:56 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 30 11:23:57 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 30 11:23:57 jbl-4312 volumio[3104]: info: Received Get System Info Dec 30 11:23:57 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 30 11:23:57 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 30 11:23:57 jbl-4312 volumio[3104]: info: Discovery: Getting this device information Dec 30 11:23:57 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioGetState Dec 30 11:23:57 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 30 11:23:57 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 30 11:23:57 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 30 11:23:59 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 30 11:23:59 jbl-4312 volumio[3104]: info: Received Get System Info Dec 30 11:23:59 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 30 11:23:59 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 30 11:23:59 jbl-4312 volumio[3104]: info: Discovery: Getting this device information Dec 30 11:23:59 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioGetState Dec 30 11:23:59 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 30 11:24:02 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:02+09:00" level=debug msg="fetched chunk 5/8, size: 524288" uri="spotify:track:32bpgwGYMZKGu8PnPkL1bN" Dec 30 11:24:05 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 30 11:24:06 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:06+09:00" level=trace msg="sent dealer ping" Dec 30 11:24:06 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:06+09:00" level=trace msg="received dealer pong" Dec 30 11:24:13 jbl-4312 volumio[3104]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/fusiondsp/rivoplus/buster/armhf Dec 30 11:24:13 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:13.442+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:13 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:13+09:00" level=debug msg="fetched chunk 6/8, size: 524288" uri="spotify:track:32bpgwGYMZKGu8PnPkL1bN" Dec 30 11:24:14 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 30 11:24:14 jbl-4312 volumio[3104]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Dec 30 11:24:14 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Dec 30 11:24:14 jbl-4312 volumio[3104]: info: Received Get System Version Dec 30 11:24:14 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 11:24:14 jbl-4312 volumio[3104]: info: Received Get System Info Dec 30 11:24:14 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 30 11:24:14 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 30 11:24:14 jbl-4312 volumio[3104]: info: Discovery: Getting this device information Dec 30 11:24:14 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioGetState Dec 30 11:24:14 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 30 11:24:16 jbl-4312 volumio[3104]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/fusiondsp/rivoplus/buster/armhf Dec 30 11:24:16 jbl-4312 volumio[3104]: info: Folder /tmp/plugins removed Dec 30 11:24:16 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:16.087+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:16 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:16.644+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:16 jbl-4312 volumio[3104]: info: Check plugin dependencies Dec 30 11:24:16 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 11:24:16 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:16.729+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:16 jbl-4312 volumio[3104]: info: Checking if plugin already exists Dec 30 11:24:16 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:16.735+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:16 jbl-4312 volumio[3104]: info: Rename folder Dec 30 11:24:16 jbl-4312 volumio[3104]: info: Folder /tmp/downloaded_plugin.zip removed Dec 30 11:24:16 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:16.787+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:16 jbl-4312 volumio[3104]: info: Move to category Dec 30 11:24:17 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:17.151+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:17 jbl-4312 volumio[3104]: info: Checking if install.sh is present Dec 30 11:24:17 jbl-4312 volumio[3104]: info: Executing install.sh Dec 30 11:24:17 jbl-4312 sudo[31328]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/audio_interface/fusiondsp/install.sh Dec 30 11:24:17 jbl-4312 sudo[31328]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 30 11:24:17 jbl-4312 volumio[3104]: info: creating filters folder and copying demo filters Dec 30 11:24:17 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:17.306+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:17 jbl-4312 volumio[3104]: info: copying demo flters Dec 30 11:24:17 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:17.354+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:17 jbl-4312 volumio[3104]: info: Installing/fusiondsp dependencies Dec 30 11:24:17 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:17.487+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:17 jbl-4312 sudo[31349]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/apt update Dec 30 11:24:17 jbl-4312 sudo[31349]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 30 11:24:17 jbl-4312 volumio[3104]: info: Get:1 http://archive.debian.org/debian buster InRelease [122 kB] Dec 30 11:24:17 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:17.739+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:17 jbl-4312 volumio[3104]: info: Get:2 https://deb.nodesource.com/node_14.x buster InRelease [4584 B] Dec 30 11:24:17 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:17.868+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:18 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:18+09:00" level=debug msg="handling update_context player command from ae9fa72e7bdf601bfefe1272a12caf7caaed7321" Dec 30 11:24:18 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:18+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:24:18 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:18+09:00" level=debug msg="sending successful reply for dealer request" Dec 30 11:24:19 jbl-4312 volumio[3104]: info: Get:3 http://archive.debian.org/debian buster/main armhf Packages [7706 kB] Dec 30 11:24:19 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:19.031+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:19 jbl-4312 volumio[3104]: info: Get:4 https://deb.nodesource.com/node_14.x buster/main armhf Packages [786 B] Dec 30 11:24:19 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:19.342+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:19 jbl-4312 volumio[3104]: info: Get:5 http://archive.debian.org/debian buster/main Translation-en [5969 kB] Dec 30 11:24:19 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:19.539+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:19 jbl-4312 volumio[3104]: info: Get:6 http://archive.debian.org/debian buster/contrib armhf Packages [40.1 kB] Dec 30 11:24:19 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:19.900+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:19 jbl-4312 volumio[3104]: info: Get:7 http://archive.debian.org/debian buster/contrib Translation-en [44.2 kB] Dec 30 11:24:19 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:19.910+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:20 jbl-4312 volumio[3104]: info: Get:8 http://archive.debian.org/debian buster/non-free armhf Packages [62.1 kB] Dec 30 11:24:20 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:20.294+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:20 jbl-4312 volumio[3104]: info: Get:9 http://archive.debian.org/debian buster/non-free Translation-en [88.9 kB] Dec 30 11:24:20 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:20.362+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=debug msg="handling play player command from ae9fa72e7bdf601bfefe1272a12caf7caaed7321" Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1EQnqst5TRi17F" Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1EQnqst5TRi17F" Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5o6L2m6fgpVvTWwhvCuMhE" Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=trace msg="emitting websocket event: will_play" Dec 30 11:24:21 jbl-4312 volumio[3104]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1EQnqst5TRi17F","uri":"spotify:track:5o6L2m6fgpVvTWwhvCuMhE","play_origin":"playlist/ondemand"}} Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=debug msg="selected format OGG_VORBIS_320 (d5a4f885d2eb72837861158a4147e54c90b2095d)" uri="spotify:track:5o6L2m6fgpVvTWwhvCuMhE" Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=debug msg="requested aes key for file d5a4f885d2eb72837861158a4147e54c90b2095d, gid: 5o6L2m6fgpVvTWwhvCuMhE" Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=trace msg="found 3 cdn urls" uri="spotify:track:5o6L2m6fgpVvTWwhvCuMhE" Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=debug msg="fetched first chunk of 26, total size is 13570584 bytes" uri="spotify:track:5o6L2m6fgpVvTWwhvCuMhE" Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=info msg="loaded track \"今夜はブギー・バック smooth rap\" (paused: false, position: 0ms, duration: 370240ms, prefetched: false)" uri="spotify:track:5o6L2m6fgpVvTWwhvCuMhE" Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=trace msg="scheduling prefetch in 340s" Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=trace msg="emitting websocket event: metadata" Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=debug msg="sending successful reply for dealer request" Dec 30 11:24:21 jbl-4312 volumio[3104]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5o6L2m6fgpVvTWwhvCuMhE","name":"今夜はブギー・バック smooth rap","artist_names":["SCHA DARA PARR","Ozawa Kenji"],"album_name":"スチャダラ外伝","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02e377a0a2eb9d62ec9d83214c","position":0,"duration":370240,"release_date":"year:1994","track_number":2,"disc_number":1}} Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=debug msg="fetched chunk 3/25, size: 524288" uri="spotify:track:5o6L2m6fgpVvTWwhvCuMhE" Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=trace msg="emitting websocket event: playing" Dec 30 11:24:21 jbl-4312 volumio[3104]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:37i9dQZF1EQnqst5TRi17F","uri":"spotify:track:5o6L2m6fgpVvTWwhvCuMhE","resume":false,"play_origin":"playlist/ondemand"}} Dec 30 11:24:21 jbl-4312 volumio[3104]: SPOTIFY: PUSH STATE SPOTIFY Dec 30 11:24:21 jbl-4312 volumio[3104]: SPOTIFY: {"status":"play","service":"spop","title":"今夜はブギー・バック smooth rap","artist":"SCHA DARA PARR, Ozawa Kenji","album":"スチャダラ外伝","albumart":"https://i.scdn.co/image/ab67616d00001e02e377a0a2eb9d62ec9d83214c","uri":"spotify:track:5o6L2m6fgpVvTWwhvCuMhE","trackType":"spotify","seek":0,"duration":370,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 30 11:24:21 jbl-4312 volumio[3104]: info: CoreCommandRouter::servicePushState Dec 30 11:24:21 jbl-4312 volumio[3104]: info: CoreStateMachine::pushState Dec 30 11:24:21 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 11:24:21 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioPushState Dec 30 11:24:21 jbl-4312 volumio[3104]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 30 11:24:21 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:21+09:00" level=debug msg="fetched chunk 1/25, size: 524288" uri="spotify:track:5o6L2m6fgpVvTWwhvCuMhE" Dec 30 11:24:22 jbl-4312 volumio[3104]: SPOTIFY: PUSH STATE SPOTIFY Dec 30 11:24:22 jbl-4312 volumio[3104]: SPOTIFY: {"status":"play","service":"spop","title":"今夜はブギー・バック smooth rap","artist":"SCHA DARA PARR, Ozawa Kenji","album":"スチャダラ外伝","albumart":"https://i.scdn.co/image/ab67616d00001e02e377a0a2eb9d62ec9d83214c","uri":"spotify:track:5o6L2m6fgpVvTWwhvCuMhE","trackType":"spotify","seek":1000,"duration":370,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 30 11:24:22 jbl-4312 volumio[3104]: info: CoreCommandRouter::servicePushState Dec 30 11:24:22 jbl-4312 volumio[3104]: info: CoreStateMachine::pushState Dec 30 11:24:22 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 11:24:22 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioPushState Dec 30 11:24:22 jbl-4312 volumio[3104]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 30 11:24:22 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:22+09:00" level=debug msg="fetched chunk 2/25, size: 524288" uri="spotify:track:5o6L2m6fgpVvTWwhvCuMhE" Dec 30 11:24:30 jbl-4312 volumio[3104]: info: Fetched 14.0 MB in 13s (1101 kB/s) Dec 30 11:24:30 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:30.463+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=debug msg="handling play player command from ae9fa72e7bdf601bfefe1272a12caf7caaed7321" Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1EQnqst5TRi17F" Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1EQnqst5TRi17F" Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:1HnRZKWyK9KyTYGwhqqKGR" Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=trace msg="emitting websocket event: will_play" Dec 30 11:24:31 jbl-4312 volumio[3104]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1EQnqst5TRi17F","uri":"spotify:track:1HnRZKWyK9KyTYGwhqqKGR","play_origin":"playlist/ondemand"}} Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=debug msg="selected format OGG_VORBIS_320 (c9348691077030a85c551ed687c4409d63ff1e96)" uri="spotify:track:1HnRZKWyK9KyTYGwhqqKGR" Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=debug msg="requested aes key for file c9348691077030a85c551ed687c4409d63ff1e96, gid: 1HnRZKWyK9KyTYGwhqqKGR" Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=trace msg="found 3 cdn urls" uri="spotify:track:1HnRZKWyK9KyTYGwhqqKGR" Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=debug msg="fetched first chunk of 17, total size is 8562313 bytes" uri="spotify:track:1HnRZKWyK9KyTYGwhqqKGR" Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:1HnRZKWyK9KyTYGwhqqKGR" Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=info msg="loaded track \"Fallin’ (feat. Neibiss)\" (paused: false, position: 1ms, duration: 205266ms, prefetched: false)" uri="spotify:track:1HnRZKWyK9KyTYGwhqqKGR" Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=trace msg="scheduling prefetch in 175s" Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=trace msg="emitting websocket event: metadata" Dec 30 11:24:31 jbl-4312 volumio[3104]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1HnRZKWyK9KyTYGwhqqKGR","name":"Fallin’ (feat. Neibiss)","artist_names":["tofubeats","Neibiss"],"album_name":"Fallin’ (feat. Neibiss)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e020d4635dcd90d49f199a271b2","position":1,"duration":205266,"release_date":"year:2025 month:11 day:19","track_number":1,"disc_number":1}} Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=debug msg="sending successful reply for dealer request" Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:1HnRZKWyK9KyTYGwhqqKGR" Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:1HnRZKWyK9KyTYGwhqqKGR" Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=trace msg="emitting websocket event: playing" Dec 30 11:24:31 jbl-4312 volumio[3104]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:37i9dQZF1EQnqst5TRi17F","uri":"spotify:track:1HnRZKWyK9KyTYGwhqqKGR","resume":false,"play_origin":"playlist/ondemand"}} Dec 30 11:24:31 jbl-4312 volumio[3104]: SPOTIFY: PUSH STATE SPOTIFY Dec 30 11:24:31 jbl-4312 volumio[3104]: SPOTIFY: {"status":"play","service":"spop","title":"Fallin’ (feat. Neibiss)","artist":"tofubeats, Neibiss","album":"Fallin’ (feat. Neibiss)","albumart":"https://i.scdn.co/image/ab67616d00001e020d4635dcd90d49f199a271b2","uri":"spotify:track:1HnRZKWyK9KyTYGwhqqKGR","trackType":"spotify","seek":1,"duration":205,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 30 11:24:31 jbl-4312 volumio[3104]: info: CoreCommandRouter::servicePushState Dec 30 11:24:31 jbl-4312 volumio[3104]: info: CoreStateMachine::pushState Dec 30 11:24:31 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 11:24:31 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioPushState Dec 30 11:24:31 jbl-4312 volumio[3104]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 30 11:24:31 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:31+09:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:1HnRZKWyK9KyTYGwhqqKGR" Dec 30 11:24:31 jbl-4312 volumio[3104]: SPOTIFY: PUSH STATE SPOTIFY Dec 30 11:24:31 jbl-4312 volumio[3104]: SPOTIFY: {"status":"play","service":"spop","title":"Fallin’ (feat. Neibiss)","artist":"tofubeats, Neibiss","album":"Fallin’ (feat. Neibiss)","albumart":"https://i.scdn.co/image/ab67616d00001e020d4635dcd90d49f199a271b2","uri":"spotify:track:1HnRZKWyK9KyTYGwhqqKGR","trackType":"spotify","seek":1,"duration":205,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 30 11:24:31 jbl-4312 volumio[3104]: info: CoreCommandRouter::servicePushState Dec 30 11:24:31 jbl-4312 volumio[3104]: info: CoreStateMachine::pushState Dec 30 11:24:31 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioPushState Dec 30 11:24:31 jbl-4312 volumio[3104]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 30 11:24:34 jbl-4312 volumio[3104]: info: Reading package lists... Dec 30 11:24:34 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:34.801+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:35 jbl-4312 volumio[3104]: info: Building dependency tree... Dec 30 11:24:35 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:35.690+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:35 jbl-4312 volumio[3104]: info: Reading state information... Dec 30 11:24:35 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:35.701+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:35 jbl-4312 volumio[3104]: info: All packages are up to date. Dec 30 11:24:35 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:35.785+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:35 jbl-4312 sudo[31349]: pam_unix(sudo:session): session closed for user root Dec 30 11:24:35 jbl-4312 sudo[31614]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/apt -y install python3-aiohttp python3-pip Dec 30 11:24:35 jbl-4312 sudo[31614]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 30 11:24:36 jbl-4312 volumio[3104]: info: Reading package lists... Dec 30 11:24:36 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:36.007+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:36 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:36+09:00" level=trace msg="sent dealer ping" Dec 30 11:24:36 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:36+09:00" level=trace msg="received dealer pong" Dec 30 11:24:36 jbl-4312 volumio[3104]: info: Building dependency tree... Dec 30 11:24:36 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:36.779+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:36 jbl-4312 volumio[3104]: info: Reading state information... Dec 30 11:24:36 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:36.789+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio[3104]: info: The following additional packages will be installed: Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.123+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio[3104]: info: binutils binutils-arm-linux-gnueabihf binutils-common build-essential bzip2 Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.132+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio[3104]: info: dh-python dpkg-dev fakeroot g++ g++-8 gcc gcc-8 libalgorithm-diff-perl Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.142+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio[3104]: info: libalgorithm-diff-xs-perl libalgorithm-merge-perl libasan5 libbinutils Dec 30 11:24:38 jbl-4312 volumio[3104]: info: libcc1-0 libexpat1-dev libfakeroot libgcc-8-dev libpython3-dev Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.152+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.153+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio[3104]: info: libpython3.7-dev libstdc++-8-dev libubsan1 make patch python-pip-whl Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.166+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio[3104]: info: python3-asn1crypto python3-async-timeout python3-attr python3-cffi-backend Dec 30 11:24:38 jbl-4312 volumio[3104]: info: python3-crypto python3-cryptography python3-dbus python3-dev Dec 30 11:24:38 jbl-4312 volumio[3104]: info: python3-entrypoints python3-gi python3-keyring python3-keyrings.alt Dec 30 11:24:38 jbl-4312 volumio[3104]: info: python3-multidict python3-secretstorage python3-setuptools python3-wheel Dec 30 11:24:38 jbl-4312 volumio[3104]: info: python3-xdg python3-yarl python3.7-dev Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.179+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.179+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.180+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.181+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.182+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio[3104]: info: Suggested packages: Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.203+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio[3104]: info: binutils-doc bzip2-doc debian-keyring gcc-8-doc libstdc++6-8-dbg Dec 30 11:24:38 jbl-4312 volumio[3104]: info: gcc-multilib autoconf automake libtool flex bison gdb gcc-doc gcc-8-locales Dec 30 11:24:38 jbl-4312 volumio[3104]: info: libgcc1-dbg libgomp1-dbg libitm1-dbg libatomic1-dbg libasan5-dbg Dec 30 11:24:38 jbl-4312 volumio[3104]: info: liblsan0-dbg libtsan0-dbg libubsan1-dbg libmpx2-dbg libquadmath0-dbg Dec 30 11:24:38 jbl-4312 volumio[3104]: info: libstdc++-8-doc make-doc ed diffutils-doc python-attr-doc python-crypto-doc Dec 30 11:24:38 jbl-4312 volumio[3104]: info: python-cryptography-doc python3-cryptography-vectors python-dbus-doc Dec 30 11:24:38 jbl-4312 volumio[3104]: info: python3-dbus-dbg gnome-keyring libkf5wallet-bin gir1.2-gnomekeyring-1.0 Dec 30 11:24:38 jbl-4312 volumio[3104]: info: python-secretstorage-doc python-setuptools-doc Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.223+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.224+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.224+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.225+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.226+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.227+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.227+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio[3104]: info: The following NEW packages will be installed: Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.301+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio[3104]: info: binutils binutils-arm-linux-gnueabihf binutils-common build-essential bzip2 Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.311+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio[3104]: info: dh-python dpkg-dev fakeroot g++ g++-8 gcc gcc-8 libalgorithm-diff-perl Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.323+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio[3104]: info: libalgorithm-diff-xs-perl libalgorithm-merge-perl libasan5 libbinutils Dec 30 11:24:38 jbl-4312 volumio[3104]: info: libcc1-0 libexpat1-dev libfakeroot libgcc-8-dev libpython3-dev Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.331+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio[3104]: info: libpython3.7-dev libstdc++-8-dev libubsan1 make patch python-pip-whl Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.347+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio[3104]: info: python3-aiohttp python3-asn1crypto python3-async-timeout python3-attr Dec 30 11:24:38 jbl-4312 volumio[3104]: info: python3-cffi-backend python3-crypto python3-cryptography python3-dbus Dec 30 11:24:38 jbl-4312 volumio[3104]: info: python3-dev python3-entrypoints python3-gi python3-keyring Dec 30 11:24:38 jbl-4312 volumio[3104]: info: python3-keyrings.alt python3-multidict python3-pip python3-secretstorage Dec 30 11:24:38 jbl-4312 volumio[3104]: info: python3-setuptools python3-wheel python3-xdg python3-yarl python3.7-dev Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.361+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.362+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.363+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.363+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio[3104]: info: 0 upgraded, 49 newly installed, 0 to remove and 0 not upgraded. Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.973+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio[3104]: info: Need to get 75.8 MB of archives. Dec 30 11:24:38 jbl-4312 volumio[3104]: info: After this operation, 165 MB of additional disk space will be used. Dec 30 11:24:38 jbl-4312 volumio[3104]: info: Get:1 http://archive.debian.org/debian buster/main armhf bzip2 armhf 1.0.6-9.2~deb10u1 [46.7 kB] Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.985+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.986+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:38 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:38.987+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:39 jbl-4312 volumio[3104]: info: Get:2 http://archive.debian.org/debian buster/main armhf binutils-common armhf 2.31.1-16 [2073 kB] Dec 30 11:24:39 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:39.233+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:40 jbl-4312 volumio[3104]: info: Get:3 http://archive.debian.org/debian buster/main armhf libbinutils armhf 2.31.1-16 [302 kB] Dec 30 11:24:40 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:40.528+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:40 jbl-4312 volumio[3104]: info: Get:4 http://archive.debian.org/debian buster/main armhf binutils-arm-linux-gnueabihf armhf 2.31.1-16 [2101 kB] Dec 30 11:24:40 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:40.553+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:41 jbl-4312 volumio[3104]: info: Get:5 http://archive.debian.org/debian buster/main armhf binutils armhf 2.31.1-16 [56.7 kB] Dec 30 11:24:41 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:41.076+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=debug msg="handling play player command from ae9fa72e7bdf601bfefe1272a12caf7caaed7321" Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1EQnqst5TRi17F" Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1EQnqst5TRi17F" Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=debug msg="loading track (paused: false, position: 2ms)" uri="spotify:track:3ANBn4Yimw0vCqvGcIrNKN" Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=trace msg="emitting websocket event: will_play" Dec 30 11:24:41 jbl-4312 volumio[3104]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1EQnqst5TRi17F","uri":"spotify:track:3ANBn4Yimw0vCqvGcIrNKN","play_origin":"playlist/ondemand"}} Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=debug msg="selected format OGG_VORBIS_320 (644a73de04aa0a3593b69879bf346396347f9cd8)" uri="spotify:track:3ANBn4Yimw0vCqvGcIrNKN" Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=debug msg="requested aes key for file 644a73de04aa0a3593b69879bf346396347f9cd8, gid: 3ANBn4Yimw0vCqvGcIrNKN" Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=trace msg="found 3 cdn urls" uri="spotify:track:3ANBn4Yimw0vCqvGcIrNKN" Dec 30 11:24:41 jbl-4312 volumio[3104]: info: Get:6 http://archive.debian.org/debian buster/main armhf libcc1-0 armhf 8.3.0-6 [38.9 kB] Dec 30 11:24:41 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:41.558+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=debug msg="fetched first chunk of 20, total size is 10057002 bytes" uri="spotify:track:3ANBn4Yimw0vCqvGcIrNKN" Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=trace msg="seek to 2ms (diff: -34ms, samples: 88, bytes: 3309)" uri="spotify:track:3ANBn4Yimw0vCqvGcIrNKN" Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=info msg="loaded track \"SHAMPOO\" (paused: false, position: 2ms, duration: 204501ms, prefetched: false)" uri="spotify:track:3ANBn4Yimw0vCqvGcIrNKN" Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:3ANBn4Yimw0vCqvGcIrNKN" Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=trace msg="scheduling prefetch in 174s" Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=trace msg="emitting websocket event: metadata" Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=debug msg="sending successful reply for dealer request" Dec 30 11:24:41 jbl-4312 volumio[3104]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3ANBn4Yimw0vCqvGcIrNKN","name":"SHAMPOO","artist_names":["PUNPEE","BIM","Elle Teresa"],"album_name":"Iced Out","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02e0b2e31343acac4c9413ba2b","position":2,"duration":204501,"release_date":"year:2025 month:7 day:9","track_number":3,"disc_number":1}} Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:3ANBn4Yimw0vCqvGcIrNKN" Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=trace msg="emitting websocket event: playing" Dec 30 11:24:41 jbl-4312 volumio[3104]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:37i9dQZF1EQnqst5TRi17F","uri":"spotify:track:3ANBn4Yimw0vCqvGcIrNKN","resume":false,"play_origin":"playlist/ondemand"}} Dec 30 11:24:41 jbl-4312 volumio[3104]: SPOTIFY: PUSH STATE SPOTIFY Dec 30 11:24:41 jbl-4312 volumio[3104]: SPOTIFY: {"status":"play","service":"spop","title":"SHAMPOO","artist":"PUNPEE, BIM, Elle Teresa","album":"Iced Out","albumart":"https://i.scdn.co/image/ab67616d00001e02e0b2e31343acac4c9413ba2b","uri":"spotify:track:3ANBn4Yimw0vCqvGcIrNKN","trackType":"spotify","seek":2,"duration":204,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 30 11:24:41 jbl-4312 volumio[3104]: info: CoreCommandRouter::servicePushState Dec 30 11:24:41 jbl-4312 volumio[3104]: info: CoreStateMachine::pushState Dec 30 11:24:41 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 11:24:41 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioPushState Dec 30 11:24:41 jbl-4312 volumio[3104]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 30 11:24:41 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:41+09:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:3ANBn4Yimw0vCqvGcIrNKN" Dec 30 11:24:42 jbl-4312 volumio[3104]: info: Get:7 http://archive.debian.org/debian buster/main armhf libasan5 armhf 8.3.0-6 [336 kB] Dec 30 11:24:42 jbl-4312 volumiologrotate[2829]: ls: cannot access '/var/log/samba/log.wb-JBL': No such file or directory Dec 30 11:24:42 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:42.042+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:42 jbl-4312 volumio[3104]: SPOTIFY: PUSH STATE SPOTIFY Dec 30 11:24:42 jbl-4312 volumio[3104]: SPOTIFY: {"status":"play","service":"spop","title":"SHAMPOO","artist":"PUNPEE, BIM, Elle Teresa","album":"Iced Out","albumart":"https://i.scdn.co/image/ab67616d00001e02e0b2e31343acac4c9413ba2b","uri":"spotify:track:3ANBn4Yimw0vCqvGcIrNKN","trackType":"spotify","seek":2,"duration":204,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 30 11:24:42 jbl-4312 volumio[3104]: info: CoreCommandRouter::servicePushState Dec 30 11:24:42 jbl-4312 volumio[3104]: info: CoreStateMachine::pushState Dec 30 11:24:42 jbl-4312 volumiologrotate[2829]: ls: cannot access '4312': No such file or directory Dec 30 11:24:42 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioPushState Dec 30 11:24:42 jbl-4312 volumio[3104]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 30 11:24:42 jbl-4312 volumio[3104]: info: Get:8 http://archive.debian.org/debian buster/main armhf libubsan1 armhf 8.3.0-6 [103 kB] Dec 30 11:24:42 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:42.553+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:42 jbl-4312 volumio[3104]: info: Get:9 http://archive.debian.org/debian buster/main armhf libgcc-8-dev armhf 8.3.0-6 [612 kB] Dec 30 11:24:42 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:42.803+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:42 jbl-4312 volumio[3104]: info: Get:10 http://archive.debian.org/debian buster/main armhf gcc-8 armhf 8.3.0-6 [7229 kB] Dec 30 11:24:42 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:42.858+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:43 jbl-4312 volumio[3104]: info: Get:11 http://archive.debian.org/debian buster/main armhf gcc armhf 4:8.3.0-1 [5204 B] Dec 30 11:24:43 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:43.577+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:43 jbl-4312 volumio[3104]: info: Get:12 http://archive.debian.org/debian buster/main armhf libstdc++-8-dev armhf 8.3.0-6 [1584 kB] Dec 30 11:24:43 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:43.595+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:43 jbl-4312 volumio[3104]: verbose: New Socket.io Connection to 192.168.3.4 from 192.168.3.13 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 7 Dec 30 11:24:43 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 30 11:24:43 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioGetVisibleSources Dec 30 11:24:43 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:24:43 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioGetState Dec 30 11:24:43 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 30 11:24:43 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 30 11:24:43 jbl-4312 volumio[3104]: info: Received Get System Info Dec 30 11:24:43 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 30 11:24:43 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 30 11:24:43 jbl-4312 volumio[3104]: info: Discovery: Getting this device information Dec 30 11:24:43 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioGetState Dec 30 11:24:43 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 30 11:24:43 jbl-4312 volumio[3104]: info: CoreCommandRouter::volumioGetState Dec 30 11:24:43 jbl-4312 volumio[3104]: info: Listing playlists Dec 30 11:24:43 jbl-4312 volumio[3104]: info: Get:13 http://archive.debian.org/debian buster/main armhf g++-8 armhf 8.3.0-6 [7463 kB] Dec 30 11:24:43 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:43.727+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:43 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 30 11:24:44 jbl-4312 volumio[3104]: info: Get:14 http://archive.debian.org/debian buster/main armhf g++ armhf 4:8.3.0-1 [1624 B] Dec 30 11:24:44 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:44.417+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:44 jbl-4312 volumio[3104]: info: Get:15 http://archive.debian.org/debian buster/main armhf make armhf 4.2.1-1.2 [327 kB] Dec 30 11:24:44 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:44.888+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:45 jbl-4312 volumio[3104]: info: Get:16 http://archive.debian.org/debian buster/main armhf patch armhf 2.7.6-3+deb10u1 [123 kB] Dec 30 11:24:45 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:45.144+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:45 jbl-4312 volumio[3104]: info: Get:17 http://archive.debian.org/debian buster/main armhf dpkg-dev all 1.19.8 [1776 kB] Dec 30 11:24:45 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:45.156+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:45 jbl-4312 volumio[3104]: info: Get:18 http://archive.debian.org/debian buster/main armhf build-essential armhf 12.6 [7568 B] Dec 30 11:24:45 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:45.405+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:45 jbl-4312 volumio[3104]: info: Get:19 http://archive.debian.org/debian buster/main armhf dh-python all 3.20190308 [99.3 kB] Dec 30 11:24:45 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:45.416+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:45 jbl-4312 volumio[3104]: info: Get:20 http://archive.debian.org/debian buster/main armhf libfakeroot armhf 1.23-1 [41.8 kB] Dec 30 11:24:45 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:45.651+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:46 jbl-4312 volumio[3104]: info: Get:21 http://archive.debian.org/debian buster/main armhf fakeroot armhf 1.23-1 [83.8 kB] Dec 30 11:24:46 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:46.130+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:46 jbl-4312 volumio[3104]: info: Get:22 http://archive.debian.org/debian buster/main armhf libalgorithm-diff-perl all 1.19.03-2 [47.9 kB] Dec 30 11:24:46 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:46.146+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:46 jbl-4312 volumio[3104]: info: Get:23 http://archive.debian.org/debian buster/main armhf libalgorithm-diff-xs-perl armhf 0.04-5+b1 [11.3 kB] Dec 30 11:24:46 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:46.619+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:46 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 30 11:24:46 jbl-4312 volumio[3104]: info: Get:24 http://archive.debian.org/debian buster/main armhf libalgorithm-merge-perl all 0.08-3 [12.7 kB] Dec 30 11:24:46 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:46.647+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:47 jbl-4312 volumio[3104]: info: Get:25 http://archive.debian.org/debian buster/main armhf libexpat1-dev armhf 2.2.6-2+deb10u4 [127 kB] Dec 30 11:24:47 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:47.388+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:47 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 30 11:24:47 jbl-4312 volumio[3104]: info: Get:26 http://archive.debian.org/debian buster/main armhf libpython3.7-dev armhf 3.7.3-2+deb10u3 [47.2 MB] Dec 30 11:24:47 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:47.653+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:52 jbl-4312 volumio[3104]: info: Get:27 http://archive.debian.org/debian buster/main armhf libpython3-dev armhf 3.7.3-1 [20.1 kB] Dec 30 11:24:52 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:52.393+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:52 jbl-4312 volumio[3104]: info: Get:28 http://archive.debian.org/debian buster/main armhf python-pip-whl all 18.1-5 [1591 kB] Dec 30 11:24:52 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:52.416+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:52 jbl-4312 go-librespot[3621]: time="2025-12-30T11:24:52+09:00" level=debug msg="fetched chunk 4/19, size: 524288" uri="spotify:track:3ANBn4Yimw0vCqvGcIrNKN" Dec 30 11:24:52 jbl-4312 volumio[3104]: info: Get:29 http://archive.debian.org/debian buster/main armhf python3-multidict armhf 4.5.2-1 [53.5 kB] Dec 30 11:24:52 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:52.796+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:52 jbl-4312 volumio[3104]: info: Enabling plugin fusiondsp Dec 30 11:24:52 jbl-4312 volumio[3104]: info: Loading plugin "fusiondsp"... Dec 30 11:24:53 jbl-4312 volumio[3104]: info: Preparing to generate the ALSA configuration file Dec 30 11:24:53 jbl-4312 volumio[3104]: info: Get:30 http://archive.debian.org/debian buster/main armhf python3-yarl armhf 1.3.0-1 [44.0 kB] Dec 30 11:24:53 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:53.634+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:53 jbl-4312 volumio[3104]: info: Asound.conf file unchanged, so no further update is needed Dec 30 11:24:53 jbl-4312 volumio[3104]: info: Output device has changed, restarting MPD Dec 30 11:24:53 jbl-4312 sudo[31699]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 11:24:53 jbl-4312 sudo[31699]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 30 11:24:53 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:53 jbl-4312 volumio[3104]: info: PLUGIN START: fusiondsp Dec 30 11:24:53 jbl-4312 sudo[31699]: pam_unix(sudo:session): session closed for user root Dec 30 11:24:53 jbl-4312 volumio[3104]: info: Loading i18n strings for locale ja Dec 30 11:24:53 jbl-4312 sudo[31701]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 11:24:53 jbl-4312 sudo[31701]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 30 11:24:53 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 30 11:24:53 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:53 jbl-4312 volumio[3104]: info: FusionDsp - mixtype--------------------- Hardware Dec 30 11:24:53 jbl-4312 volumio[3104]: info: Preparing to generate the ALSA configuration file Dec 30 11:24:53 jbl-4312 systemd[1]: Stopping Music Player Daemon... Dec 30 11:24:53 jbl-4312 volumio[3104]: info: Done. Dec 30 11:24:53 jbl-4312 volumio[3104]: info: MPD Permissions set Dec 30 11:24:53 jbl-4312 volumio[3104]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 30 11:24:53 jbl-4312 volumio[3104]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 30 11:24:53 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:53 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:53 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:53 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:53 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:53 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:53 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:53 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:53 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:24:53 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Dec 30 11:24:53 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:53 jbl-4312 volumio[3104]: info: Asound.conf file unchanged, so no further update is needed Dec 30 11:24:53 jbl-4312 volumio[3104]: info: Output device has changed, restarting MPD Dec 30 11:24:53 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:53 jbl-4312 sudo[31711]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 11:24:53 jbl-4312 sudo[31711]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 30 11:24:53 jbl-4312 sudo[31711]: pam_unix(sudo:session): session closed for user root Dec 30 11:24:53 jbl-4312 volumio[3104]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 30 11:24:53 jbl-4312 sudo[31713]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 11:24:53 jbl-4312 sudo[31713]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 30 11:24:53 jbl-4312 systemd[1]: mpd.service: Succeeded. Dec 30 11:24:53 jbl-4312 systemd[1]: Stopped Music Player Daemon. Dec 30 11:24:53 jbl-4312 systemd[1]: Starting Music Player Daemon... Dec 30 11:24:53 jbl-4312 systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Dec 30 11:24:53 jbl-4312 systemd[1]: mpd.service: Succeeded. Dec 30 11:24:54 jbl-4312 systemd[1]: Stopped Music Player Daemon. Dec 30 11:24:54 jbl-4312 systemd[1]: Starting Music Player Daemon... Dec 30 11:24:54 jbl-4312 sudo[31724]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 11:24:54 jbl-4312 sudo[31724]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 30 11:24:54 jbl-4312 sudo[31724]: pam_unix(sudo:session): session closed for user root Dec 30 11:24:54 jbl-4312 volumio[3104]: info: MPD Permissions set Dec 30 11:24:54 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:54 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:54 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:54 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:54 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:54 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:54 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:54 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:54 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:24:54 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Dec 30 11:24:54 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:54 jbl-4312 volumio[3104]: info: Get:31 http://archive.debian.org/debian buster/main armhf python3-async-timeout all 3.0.1-1 [6292 B] Dec 30 11:24:54 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:54.605+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:54 jbl-4312 volumio[3104]: info: Get:32 http://archive.debian.org/debian buster/main armhf python3-attr all 18.2.0-1 [37.3 kB] Dec 30 11:24:54 jbl-4312 volumio[3104]: info: Get:33 http://archive.debian.org/debian buster/main armhf python3-aiohttp armhf 3.5.1-1+deb10u1 [245 kB] Dec 30 11:24:54 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:54.613+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:54 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:54.614+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:55 jbl-4312 volumio[3104]: info: Get:34 http://archive.debian.org/debian buster/main armhf python3-asn1crypto all 0.24.0-1 [78.2 kB] Dec 30 11:24:55 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:55.062+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:55 jbl-4312 volumio[3104]: info: Get:35 http://archive.debian.org/debian buster/main armhf python3-cffi-backend armhf 1.12.2-1 [70.2 kB] Dec 30 11:24:55 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:55.068+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:55 jbl-4312 volumio[3104]: info: Get:36 http://archive.debian.org/debian buster/main armhf python3-crypto armhf 2.6.1-9+b1 [257 kB] Dec 30 11:24:55 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:55.084+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:55 jbl-4312 volumio[3104]: info: Get:37 http://archive.debian.org/debian buster/main armhf python3-cryptography armhf 2.6.1-3+deb10u2 [189 kB] Dec 30 11:24:55 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:55.297+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:55 jbl-4312 volumio[3104]: info: Get:38 http://archive.debian.org/debian buster/main armhf python3-dbus armhf 1.2.8-3 [96.3 kB] Dec 30 11:24:55 jbl-4312 volumio5-onboarding[3544]: time=2025-12-30T11:24:55.541+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Dec 30 11:24:55 jbl-4312 volumio[3104]: info: camilladsp spawned new process with pid undefined, instance 1, run: true Dec 30 11:24:55 jbl-4312 volumio[3104]: info: camilladsp service started and running in background, instance 1 Dec 30 11:24:55 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:24:55 jbl-4312 volumio[3104]: /bin/sh: 1: /data/plugins/audio_interface/fusiondsp/hw_params: not found Dec 30 11:24:55 jbl-4312 volumio[3104]: error: FusionDsp - ----Hw detection failed :Error: Command failed: /data/plugins/audio_interface/fusiondsp/hw_params volumioHw >/data/configuration/audio_interface/fusiondsp/hwinfo.json Dec 30 11:24:55 jbl-4312 volumio[3104]: /bin/sh: 1: /data/plugins/audio_interface/fusiondsp/hw_params: not found Dec 30 11:24:55 jbl-4312 volumio[3104]: info: FusionDsp loaded Dec 30 11:24:55 jbl-4312 volumio[3104]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 30 11:24:55 jbl-4312 sudo[31745]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Dec 30 11:24:55 jbl-4312 sudo[31745]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 30 11:24:55 jbl-4312 volumio[3104]: info: FusionDsp - Reporting Fusion DSP Enabled Dec 30 11:24:55 jbl-4312 volumio[3104]: info: Adding Signal Path Element [object Object] Dec 30 11:24:55 jbl-4312 volumio[3104]: info: Adding fusiondspeq DSP Signal Path Element Dec 30 11:24:55 jbl-4312 volumio[3104]: info: FusionDsp - ---- installed callbackRead Dec 30 11:24:55 jbl-4312 volumio[3104]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 11:24:55 jbl-4312 sudo[31745]: pam_unix(sudo:session): session closed for user root Dec 30 11:24:55 jbl-4312 volumio[3104]: Error: spawn /data/plugins/audio_interface/fusiondsp/camilladsp ENOENT Dec 30 11:24:55 jbl-4312 volumio[3104]: at Process.ChildProcess._handle.onexit (internal/child_process.js:277:19) Dec 30 11:24:55 jbl-4312 volumio[3104]: at onErrorNT (internal/child_process.js:472:16) Dec 30 11:24:55 jbl-4312 volumio[3104]: at processTicksAndRejections (internal/process/task_queues.js:82:21) { Dec 30 11:24:55 jbl-4312 volumio[3104]: errno: -2, Dec 30 11:24:55 jbl-4312 volumio[3104]: code: 'ENOENT', Dec 30 11:24:55 jbl-4312 volumio[3104]: syscall: 'spawn /data/plugins/audio_interface/fusiondsp/camilladsp', Dec 30 11:24:55 jbl-4312 volumio[3104]: path: '/data/plugins/audio_interface/fusiondsp/camilladsp', Dec 30 11:24:55 jbl-4312 volumio[3104]: spawnargs: [ Dec 30 11:24:55 jbl-4312 volumio[3104]: '-p', Dec 30 11:24:55 jbl-4312 volumio[3104]: 9876, Dec 30 11:24:55 jbl-4312 volumio[3104]: '-o', Dec 30 11:24:55 jbl-4312 volumio[3104]: '/tmp/camilladsp.log', Dec 30 11:24:55 jbl-4312 volumio[3104]: '-l', Dec 30 11:24:55 jbl-4312 volumio[3104]: 'warn', Dec 30 11:24:55 jbl-4312 volumio[3104]: '/data/configuration/audio_interface/fusiondsp/camilladsp.yml' Dec 30 11:24:55 jbl-4312 volumio[3104]: ] Dec 30 11:24:55 jbl-4312 volumio[3104]: } Dec 30 11:24:55 jbl-4312 volumio[3104]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 11:24:56 jbl-4312 mpd[31727]: Dec 30 11:24 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 30 11:24:56 jbl-4312 systemd[1]: Started Music Player Daemon. Dec 30 11:24:56 jbl-4312 sudo[31713]: pam_unix(sudo:session): session closed for user root Dec 30 11:24:56 jbl-4312 sudo[31701]: pam_unix(sudo:session): session closed for user root Dec 30 11:24:56 jbl-4312 sudo[31758]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-12-30 11:23 Dec 30 11:24:56 jbl-4312 sudo[31758]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="b43c85cc0006d3f1efecba101311ec96e334d1fd" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="2f25e1a98e53e2dbc4f3878604e250b0379f3ea4" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivoplus" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 11 Dec 2025 06:47:33 PM CET" VOLUMIO_VERSION="3.886" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo Plus" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo Plus" VOLUMIO_HASH="9e8aa5d6afb5e5d87a87bafae7aa5647"