Apr 12 18:13:05 dac go-librespot[1673]: time="2026-04-12T18:13:05+05:30" level=debug msg="fetched chunk 7/18, size: 524288" uri="spotify:track:16DEAeC70XuyW8ctAddFCC" Apr 12 18:13:07 dac go-librespot[1673]: time="2026-04-12T18:13:07+05:30" level=debug msg="handling play player command from ca7f795144ac718384138a333b45361b9f8d2c8c" Apr 12 18:13:07 dac go-librespot[1673]: time="2026-04-12T18:13:07+05:30" level=debug msg="resolved context of track" uri="spotify:search:shoot+from+" Apr 12 18:13:07 dac go-librespot[1673]: time="2026-04-12T18:13:07+05:30" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:search:shoot+from+" Apr 12 18:13:07 dac go-librespot[1673]: time="2026-04-12T18:13:07+05:30" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2tuiGLoE9ZNqAamqylsafY" Apr 12 18:13:07 dac go-librespot[1673]: time="2026-04-12T18:13:07+05:30" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 12 18:13:07 dac go-librespot[1673]: time="2026-04-12T18:13:07+05:30" level=trace msg="emitting websocket event: will_play" Apr 12 18:13:07 dac volumio[1235]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:search:shoot+from+","uri":"spotify:track:2tuiGLoE9ZNqAamqylsafY","play_origin":"search"}} Apr 12 18:13:07 dac go-librespot[1673]: time="2026-04-12T18:13:07+05:30" level=debug msg="selected format OGG_VORBIS_320 (2d441b9eea2f34971b8ad31d61840826ee5a90aa)" uri="spotify:track:2tuiGLoE9ZNqAamqylsafY" Apr 12 18:13:07 dac go-librespot[1673]: time="2026-04-12T18:13:07+05:30" level=debug msg="requested aes key for file 2d441b9eea2f34971b8ad31d61840826ee5a90aa, gid: 2tuiGLoE9ZNqAamqylsafY" Apr 12 18:13:08 dac go-librespot[1673]: time="2026-04-12T18:13:08+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 149" Apr 12 18:13:08 dac go-librespot[1673]: time="2026-04-12T18:13:08+05:30" level=trace msg="found 2 cdn urls" uri="spotify:track:2tuiGLoE9ZNqAamqylsafY" Apr 12 18:13:09 dac go-librespot[1673]: time="2026-04-12T18:13:09+05:30" level=debug msg="fetched first chunk of 20, total size is 10396652 bytes" uri="spotify:track:2tuiGLoE9ZNqAamqylsafY" Apr 12 18:13:09 dac go-librespot[1673]: time="2026-04-12T18:13:09+05:30" level=info msg="loaded track \"Shoot from the Heart\" (paused: false, position: 0ms, duration: 266906ms, prefetched: false)" uri="spotify:track:2tuiGLoE9ZNqAamqylsafY" Apr 12 18:13:09 dac go-librespot[1673]: time="2026-04-12T18:13:09+05:30" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:2tuiGLoE9ZNqAamqylsafY" Apr 12 18:13:09 dac go-librespot[1673]: time="2026-04-12T18:13:09+05:30" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 12 18:13:09 dac go-librespot[1673]: time="2026-04-12T18:13:09+05:30" level=trace msg="scheduling prefetch in 237s" Apr 12 18:13:09 dac go-librespot[1673]: time="2026-04-12T18:13:09+05:30" level=trace msg="emitting websocket event: metadata" Apr 12 18:13:09 dac go-librespot[1673]: time="2026-04-12T18:13:09+05:30" level=debug msg="sending successful reply for dealer request" Apr 12 18:13:09 dac volumio[1235]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2tuiGLoE9ZNqAamqylsafY","name":"Shoot from the Heart","artist_names":["Judie Tzuke"],"album_name":"Ritmo","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0252a6bb4daafdbfaff0bfb7d5","position":0,"duration":266906,"release_date":"year:1983 month:9 day:1","track_number":3,"disc_number":1}} Apr 12 18:13:09 dac go-librespot[1673]: time="2026-04-12T18:13:09+05:30" level=debug msg="skipping dealer message" uri=playback-settings/content-settings-update Apr 12 18:13:09 dac go-librespot[1673]: time="2026-04-12T18:13:09+05:30" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:2tuiGLoE9ZNqAamqylsafY" Apr 12 18:13:09 dac go-librespot[1673]: time="2026-04-12T18:13:09+05:30" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 12 18:13:09 dac go-librespot[1673]: time="2026-04-12T18:13:09+05:30" level=trace msg="emitting websocket event: playing" Apr 12 18:13:09 dac volumio[1235]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:search:shoot+from+","uri":"spotify:track:2tuiGLoE9ZNqAamqylsafY","resume":false,"play_origin":"search"}} Apr 12 18:13:09 dac volumio[1235]: SPOTIFY: PUSH STATE SPOTIFY Apr 12 18:13:09 dac volumio[1235]: SPOTIFY: {"status":"play","service":"spop","title":"Shoot from the Heart","artist":"Judie Tzuke","album":"Ritmo","albumart":"https://i.scdn.co/image/ab67616d00001e0252a6bb4daafdbfaff0bfb7d5","uri":"spotify:track:2tuiGLoE9ZNqAamqylsafY","trackType":"spotify","seek":0,"duration":266,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 12 18:13:09 dac volumio[1235]: info: CoreCommandRouter::servicePushState Apr 12 18:13:09 dac volumio[1235]: info: CoreStateMachine::pushState Apr 12 18:13:09 dac volumio[1235]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 18:13:09 dac volumio[1235]: info: CoreCommandRouter::volumioPushState Apr 12 18:13:09 dac go-librespot[1673]: time="2026-04-12T18:13:09+05:30" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:2tuiGLoE9ZNqAamqylsafY" Apr 12 18:13:09 dac volumio5-onboarding[1586]: time=2026-04-12T18:13:09.925+05:30 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.19:49630 @ 0x2401890" state=STATUS_PLAYING positionMs=0 volume=31 Apr 12 18:13:09 dac volumio5-onboarding[1586]: time=2026-04-12T18:13:09.925+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.19:49630 @ 0x2401890" id=spotify:track:2tuiGLoE9ZNqAamqylsafY title="Shoot from the Heart" Apr 12 18:13:09 dac volumio[1235]: SPOTIFY: RECEIVED VOLUMIO VOLUME 31 Apr 12 18:13:10 dac volumio[1235]: SPOTIFY: PUSH STATE SPOTIFY Apr 12 18:13:10 dac volumio[1235]: SPOTIFY: {"status":"play","service":"spop","title":"Shoot from the Heart","artist":"Judie Tzuke","album":"Ritmo","albumart":"https://i.scdn.co/image/ab67616d00001e0252a6bb4daafdbfaff0bfb7d5","uri":"spotify:track:2tuiGLoE9ZNqAamqylsafY","trackType":"spotify","seek":0,"duration":266,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 12 18:13:10 dac volumio[1235]: info: CoreCommandRouter::servicePushState Apr 12 18:13:10 dac volumio[1235]: info: CoreStateMachine::pushState Apr 12 18:13:10 dac volumio[1235]: info: CoreCommandRouter::volumioPushState Apr 12 18:13:10 dac volumio5-onboarding[1586]: time=2026-04-12T18:13:10.223+05:30 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.19:49630 @ 0x2401890" state=STATUS_PLAYING positionMs=0 volume=31 Apr 12 18:13:10 dac volumio5-onboarding[1586]: time=2026-04-12T18:13:10.223+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.19:49630 @ 0x2401890" id=spotify:track:2tuiGLoE9ZNqAamqylsafY title="Shoot from the Heart" Apr 12 18:13:10 dac volumio[1235]: SPOTIFY: RECEIVED VOLUMIO VOLUME 31 Apr 12 18:13:13 dac go-librespot[1673]: time="2026-04-12T18:13:13+05:30" level=trace msg="received accesspoint ping" Apr 12 18:13:13 dac go-librespot[1673]: time="2026-04-12T18:13:13+05:30" level=trace msg="received accesspoint pong ack" Apr 12 18:13:14 dac go-librespot[1673]: time="2026-04-12T18:13:14+05:30" level=trace msg="sent dealer ping" Apr 12 18:13:14 dac go-librespot[1673]: time="2026-04-12T18:13:14+05:30" level=trace msg="received dealer pong" Apr 12 18:13:24 dac go-librespot[1673]: time="2026-04-12T18:13:24+05:30" level=debug msg="fetched chunk 4/19, size: 524288" uri="spotify:track:2tuiGLoE9ZNqAamqylsafY" Apr 12 18:13:34 dac go-librespot[1673]: time="2026-04-12T18:13:34+05:30" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1EIWCOWyOLZX0d" Apr 12 18:13:34 dac go-librespot[1673]: time="2026-04-12T18:13:34+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 137" Apr 12 18:13:37 dac go-librespot[1673]: time="2026-04-12T18:13:37+05:30" level=debug msg="fetched chunk 5/19, size: 524288" uri="spotify:track:2tuiGLoE9ZNqAamqylsafY" Apr 12 18:13:44 dac go-librespot[1673]: time="2026-04-12T18:13:44+05:30" level=trace msg="sent dealer ping" Apr 12 18:13:44 dac go-librespot[1673]: time="2026-04-12T18:13:44+05:30" level=trace msg="received dealer pong" Apr 12 18:13:50 dac go-librespot[1673]: time="2026-04-12T18:13:50+05:30" level=debug msg="fetched chunk 6/19, size: 524288" uri="spotify:track:2tuiGLoE9ZNqAamqylsafY" Apr 12 18:14:00 dac go-librespot[1673]: time="2026-04-12T18:14:00+05:30" level=debug msg="update volume requested to 22937/65535" Apr 12 18:14:01 dac go-librespot[1673]: time="2026-04-12T18:14:01+05:30" level=debug msg="put connect state because VOLUME_CHANGED" Apr 12 18:14:01 dac go-librespot[1673]: time="2026-04-12T18:14:01+05:30" level=trace msg="emitting websocket event: volume" Apr 12 18:14:01 dac go-librespot[1673]: time="2026-04-12T18:14:01+05:30" level=debug msg="update volume requested to 25559/65535" Apr 12 18:14:01 dac volumio[1235]: SPOTIFY: received: {"type":"volume","data":{"value":35,"max":100}} Apr 12 18:14:01 dac volumio[1235]: SPOTIFY: RECEIVED SPOTIFY VOLUME 35 Apr 12 18:14:01 dac volumio[1235]: info: Setting Volumio Volume from Spotify: 35 Apr 12 18:14:01 dac volumio[1235]: info: CoreCommandRouter::executeOnPlugin: allo_relay_attenuator , alsavolume Apr 12 18:14:01 dac volumio[1235]: info: Allo Relay Attenuator: alsavolume called with 35 Apr 12 18:14:01 dac sudo[4620]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/fn-rattenuc -c SET_VOLUME=35 Apr 12 18:14:01 dac sudo[4620]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 18:14:01 dac fn-rattenu[1701]: Error: Writing to I2C Apr 12 18:14:01 dac sudo[4620]: pam_unix(sudo:session): session closed for user root Apr 12 18:14:01 dac volumio[1235]: info: Allo Relay Attenuator: Hardware volume set to 35 Apr 12 18:14:01 dac volumio[1235]: info: CoreCommandRouter::volumioGetState Apr 12 18:14:01 dac volumio[1235]: info: CoreStateMachine::pushState Apr 12 18:14:01 dac volumio[1235]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 18:14:01 dac volumio[1235]: info: CoreCommandRouter::volumioPushState Apr 12 18:14:01 dac volumio[1235]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 12 18:14:01 dac volumio5-onboarding[1586]: time=2026-04-12T18:14:01.110+05:30 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.19:49630 @ 0x2401890" state=STATUS_PLAYING positionMs=51000 volume=35 Apr 12 18:14:01 dac volumio5-onboarding[1586]: time=2026-04-12T18:14:01.110+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.19:49630 @ 0x2401890" id=spotify:track:2tuiGLoE9ZNqAamqylsafY title="Shoot from the Heart" Apr 12 18:14:01 dac volumio[1235]: TypeError: Cannot read properties of undefined (reading 'vol') Apr 12 18:14:01 dac volumio[1235]: at /data/plugins/music_service/ytcr/dist/index.js:300:35 Apr 12 18:14:01 dac volumio[1235]: at CoreCommandRouter.callCallback (/volumio/app/index.js:214:9) Apr 12 18:14:01 dac volumio[1235]: at CoreCommandRouter.volumioupdatevolume (/volumio/app/index.js:143:8) Apr 12 18:14:01 dac volumio[1235]: at Promise._successFn (/volumio/app/index.js:137:16) Apr 12 18:14:01 dac volumio[1235]: at nextTickCallback (/data/plugins/system_hardware/allo_relay_attenuator/node_modules/kew/kew.js:47:28) Apr 12 18:14:01 dac volumio[1235]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Apr 12 18:14:01 dac volumio[1235]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 12 18:14:01 dac go-librespot[1673]: time="2026-04-12T18:14:01+05:30" level=debug msg="put connect state because VOLUME_CHANGED" Apr 12 18:14:01 dac go-librespot[1673]: time="2026-04-12T18:14:01+05:30" level=trace msg="emitting websocket event: volume" Apr 12 18:14:01 dac go-librespot[1673]: time="2026-04-12T18:14:01+05:30" level=debug msg="update volume requested to 28180/65535" Apr 12 18:14:01 dac sudo[4636]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-04-12 18:13' Apr 12 18:14:01 dac sudo[4636]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"