Jun 02 22:27:18 volumio go-librespot[12529]: time="2026-06-02T22:27:18+09:00" level=trace msg="emitting websocket event: not_playing" Jun 02 22:27:18 volumio go-librespot[12529]: time="2026-06-02T22:27:18+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2u6gOYRHuN06LMQDHTwUrl" Jun 02 22:27:18 volumio volumio[12339]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:playlist:7IUIgdUMzpoPQKX2MZrjqt","uri":"spotify:track:5sdQOyqq2IDhvmx2lHOpwd","play_origin":"playlist"}} Jun 02 22:27:18 volumio volumio[12339]: error: Failed to decode event: not_playing Jun 02 22:27:18 volumio go-librespot[12529]: time="2026-06-02T22:27:18+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 22:27:18 volumio go-librespot[12529]: time="2026-06-02T22:27:18+09:00" level=trace msg="emitting websocket event: will_play" Jun 02 22:27:18 volumio go-librespot[12529]: time="2026-06-02T22:27:18+09:00" level=info msg="loaded track \"My Romance (take 1)\" (paused: false, position: 0ms, duration: 431213ms, prefetched: true)" uri="spotify:track:2u6gOYRHuN06LMQDHTwUrl" Jun 02 22:27:18 volumio volumio[12339]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:7IUIgdUMzpoPQKX2MZrjqt","uri":"spotify:track:2u6gOYRHuN06LMQDHTwUrl","play_origin":"playlist"}} Jun 02 22:27:19 volumio go-librespot[12529]: time="2026-06-02T22:27:19+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 22:27:19 volumio go-librespot[12529]: time="2026-06-02T22:27:19+09:00" level=trace msg="scheduling prefetch in 401s" Jun 02 22:27:19 volumio go-librespot[12529]: time="2026-06-02T22:27:19+09:00" level=trace msg="emitting websocket event: metadata" Jun 02 22:27:19 volumio volumio[12339]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2u6gOYRHuN06LMQDHTwUrl","name":"My Romance (take 1)","artist_names":["Bill Evans Trio"],"album_name":"Waltz For Debby (Original Jazz Classics Remaster 2010)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b97f82fd92c92369eafd9a47","position":0,"duration":431213,"release_date":"year:1961","track_number":4,"disc_number":1}} Jun 02 22:27:19 volumio go-librespot[12529]: time="2026-06-02T22:27:19+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 22:27:19 volumio go-librespot[12529]: time="2026-06-02T22:27:19+09:00" level=trace msg="emitting websocket event: playing" Jun 02 22:27:19 volumio volumio[12339]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:7IUIgdUMzpoPQKX2MZrjqt","uri":"spotify:track:2u6gOYRHuN06LMQDHTwUrl","resume":false,"play_origin":"playlist"}} Jun 02 22:27:19 volumio volumio[12339]: SPOTIFY: PUSH STATE SPOTIFY Jun 02 22:27:19 volumio volumio[12339]: SPOTIFY: {"status":"play","service":"spop","title":"My Romance (take 1)","artist":"Bill Evans Trio","album":"Waltz For Debby (Original Jazz Classics Remaster 2010)","albumart":"https://i.scdn.co/image/ab67616d00001e02b97f82fd92c92369eafd9a47","uri":"spotify:track:2u6gOYRHuN06LMQDHTwUrl","trackType":"spotify","seek":0,"duration":431,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 02 22:27:19 volumio volumio[12339]: info: CoreCommandRouter::servicePushState Jun 02 22:27:19 volumio volumio[12339]: info: CoreStateMachine::pushState Jun 02 22:27:19 volumio volumio[12339]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 22:27:19 volumio volumio[12339]: info: CoreCommandRouter::volumioPushState Jun 02 22:27:19 volumio volumio[12339]: SPOTIFY: PUSH STATE SPOTIFY Jun 02 22:27:19 volumio volumio[12339]: SPOTIFY: {"status":"play","service":"spop","title":"My Romance (take 1)","artist":"Bill Evans Trio","album":"Waltz For Debby (Original Jazz Classics Remaster 2010)","albumart":"https://i.scdn.co/image/ab67616d00001e02b97f82fd92c92369eafd9a47","uri":"spotify:track:2u6gOYRHuN06LMQDHTwUrl","trackType":"spotify","seek":1000,"duration":431,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 02 22:27:19 volumio volumio[12339]: info: CoreCommandRouter::servicePushState Jun 02 22:27:19 volumio volumio[12339]: info: CoreStateMachine::pushState Jun 02 22:27:19 volumio volumio[12339]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 22:27:19 volumio volumio[12339]: info: CoreCommandRouter::volumioPushState Jun 02 22:27:19 volumio go-librespot[12529]: time="2026-06-02T22:27:19+09:00" level=trace msg="received accesspoint ping" Jun 02 22:27:19 volumio go-librespot[12529]: time="2026-06-02T22:27:19+09:00" level=trace msg="received accesspoint pong ack" Jun 02 22:27:20 volumio go-librespot[12529]: time="2026-06-02T22:27:20+09:00" level=trace msg="sent dealer ping" Jun 02 22:27:20 volumio go-librespot[12529]: time="2026-06-02T22:27:20+09:00" level=trace msg="received dealer pong" Jun 02 22:27:29 volumio volumio[12339]: info: CoreCommandRouter::volumioNext Jun 02 22:27:29 volumio volumio[12339]: info: CoreStateMachine::next Jun 02 22:27:29 volumio volumio[12339]: info: Spotify next Jun 02 22:27:29 volumio volumio[12339]: info: Sending Spotify command to local API: /player/next Jun 02 22:27:29 volumio go-librespot[12529]: time="2026-06-02T22:27:29+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4e1aewX6ATPcdfQIqr7gqO" Jun 02 22:27:29 volumio go-librespot[12529]: time="2026-06-02T22:27:29+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 22:27:29 volumio go-librespot[12529]: time="2026-06-02T22:27:29+09:00" level=trace msg="emitting websocket event: will_play" Jun 02 22:27:29 volumio volumio[12339]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:7IUIgdUMzpoPQKX2MZrjqt","uri":"spotify:track:4e1aewX6ATPcdfQIqr7gqO","play_origin":"playlist"}} Jun 02 22:27:29 volumio go-librespot[12529]: time="2026-06-02T22:27:29+09:00" level=debug msg="selected format OGG_VORBIS_320 (e1a414d9ab467c4a1c91680faa107a4bd4fc9013)" uri="spotify:track:4e1aewX6ATPcdfQIqr7gqO" Jun 02 22:27:29 volumio go-librespot[12529]: time="2026-06-02T22:27:29+09:00" level=debug msg="requested aes key for file e1a414d9ab467c4a1c91680faa107a4bd4fc9013, gid: 4e1aewX6ATPcdfQIqr7gqO" Jun 02 22:27:29 volumio go-librespot[12529]: time="2026-06-02T22:27:29+09:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4e1aewX6ATPcdfQIqr7gqO" Jun 02 22:27:29 volumio go-librespot[12529]: time="2026-06-02T22:27:29+09:00" level=debug msg="fetched first chunk of 13, total size is 6513594 bytes" uri="spotify:track:4e1aewX6ATPcdfQIqr7gqO" Jun 02 22:27:29 volumio go-librespot[12529]: time="2026-06-02T22:27:29+09:00" level=info msg="loaded track \"Sticky\" (paused: false, position: 0ms, duration: 157120ms, prefetched: false)" uri="spotify:track:4e1aewX6ATPcdfQIqr7gqO" Jun 02 22:27:29 volumio go-librespot[12529]: time="2026-06-02T22:27:29+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 22:27:29 volumio go-librespot[12529]: time="2026-06-02T22:27:29+09:00" level=trace msg="scheduling prefetch in 127s" Jun 02 22:27:29 volumio go-librespot[12529]: time="2026-06-02T22:27:29+09:00" level=trace msg="emitting websocket event: metadata" Jun 02 22:27:29 volumio volumio[12339]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4e1aewX6ATPcdfQIqr7gqO","name":"Sticky","artist_names":["KISS OF LIFE"],"album_name":"Sticky","album_cover_url":"https://i.scdn.co/image/ab67616d00001e024cd7f69b85766b3d3035c27c","position":0,"duration":157120,"release_date":"year:2024 month:7 day:1","track_number":1,"disc_number":1}} Jun 02 22:27:29 volumio go-librespot[12529]: time="2026-06-02T22:27:29+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 22:27:29 volumio go-librespot[12529]: time="2026-06-02T22:27:29+09:00" level=trace msg="emitting websocket event: playing" Jun 02 22:27:29 volumio volumio[12339]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:7IUIgdUMzpoPQKX2MZrjqt","uri":"spotify:track:4e1aewX6ATPcdfQIqr7gqO","resume":false,"play_origin":"playlist"}} Jun 02 22:27:29 volumio volumio[12339]: SPOTIFY: PUSH STATE SPOTIFY Jun 02 22:27:29 volumio volumio[12339]: SPOTIFY: {"status":"play","service":"spop","title":"Sticky","artist":"KISS OF LIFE","album":"Sticky","albumart":"https://i.scdn.co/image/ab67616d00001e024cd7f69b85766b3d3035c27c","uri":"spotify:track:4e1aewX6ATPcdfQIqr7gqO","trackType":"spotify","seek":0,"duration":157,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 02 22:27:29 volumio volumio[12339]: info: CoreCommandRouter::servicePushState Jun 02 22:27:29 volumio volumio[12339]: info: CoreStateMachine::pushState Jun 02 22:27:29 volumio volumio[12339]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 22:27:29 volumio volumio[12339]: info: CoreCommandRouter::volumioPushState Jun 02 22:27:30 volumio go-librespot[12529]: time="2026-06-02T22:27:30+09:00" level=debug msg="fetched chunk 1/12, size: 524288" uri="spotify:track:4e1aewX6ATPcdfQIqr7gqO" Jun 02 22:27:30 volumio volumio[12339]: SPOTIFY: PUSH STATE SPOTIFY Jun 02 22:27:30 volumio volumio[12339]: SPOTIFY: {"status":"play","service":"spop","title":"Sticky","artist":"KISS OF LIFE","album":"Sticky","albumart":"https://i.scdn.co/image/ab67616d00001e024cd7f69b85766b3d3035c27c","uri":"spotify:track:4e1aewX6ATPcdfQIqr7gqO","trackType":"spotify","seek":1000,"duration":157,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 02 22:27:30 volumio volumio[12339]: info: CoreCommandRouter::servicePushState Jun 02 22:27:30 volumio volumio[12339]: info: CoreStateMachine::pushState Jun 02 22:27:30 volumio volumio[12339]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 22:27:30 volumio volumio[12339]: info: CoreCommandRouter::volumioPushState Jun 02 22:27:30 volumio go-librespot[12529]: time="2026-06-02T22:27:30+09:00" level=debug msg="fetched chunk 2/12, size: 524288" uri="spotify:track:4e1aewX6ATPcdfQIqr7gqO" Jun 02 22:27:30 volumio go-librespot[12529]: time="2026-06-02T22:27:30+09:00" level=debug msg="fetched chunk 3/12, size: 524288" uri="spotify:track:4e1aewX6ATPcdfQIqr7gqO" Jun 02 22:27:33 volumio volumio[12339]: info: CoreCommandRouter::volumioNext Jun 02 22:27:33 volumio volumio[12339]: info: CoreStateMachine::next Jun 02 22:27:33 volumio volumio[12339]: info: Spotify next Jun 02 22:27:33 volumio volumio[12339]: info: Sending Spotify command to local API: /player/next Jun 02 22:27:33 volumio go-librespot[12529]: time="2026-06-02T22:27:33+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4P5ozkI1bxiGxA5rZ27jlO" Jun 02 22:27:33 volumio go-librespot[12529]: time="2026-06-02T22:27:33+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 22:27:33 volumio go-librespot[12529]: time="2026-06-02T22:27:33+09:00" level=trace msg="emitting websocket event: will_play" Jun 02 22:27:33 volumio volumio[12339]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:7IUIgdUMzpoPQKX2MZrjqt","uri":"spotify:track:4P5ozkI1bxiGxA5rZ27jlO","play_origin":"playlist"}} Jun 02 22:27:33 volumio go-librespot[12529]: time="2026-06-02T22:27:33+09:00" level=debug msg="selected format OGG_VORBIS_320 (d3b1edf66de2f77cbbadf57a995a664548c0890c)" uri="spotify:track:4P5ozkI1bxiGxA5rZ27jlO" Jun 02 22:27:33 volumio go-librespot[12529]: time="2026-06-02T22:27:33+09:00" level=debug msg="requested aes key for file d3b1edf66de2f77cbbadf57a995a664548c0890c, gid: 4P5ozkI1bxiGxA5rZ27jlO" Jun 02 22:27:33 volumio go-librespot[12529]: time="2026-06-02T22:27:33+09:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4P5ozkI1bxiGxA5rZ27jlO" Jun 02 22:27:33 volumio go-librespot[12529]: time="2026-06-02T22:27:33+09:00" level=debug msg="fetched first chunk of 15, total size is 7809204 bytes" uri="spotify:track:4P5ozkI1bxiGxA5rZ27jlO" Jun 02 22:27:33 volumio go-librespot[12529]: time="2026-06-02T22:27:33+09:00" level=info msg="loaded track \"Bubble\" (paused: false, position: 0ms, duration: 179275ms, prefetched: false)" uri="spotify:track:4P5ozkI1bxiGxA5rZ27jlO" Jun 02 22:27:33 volumio go-librespot[12529]: time="2026-06-02T22:27:33+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 22:27:33 volumio go-librespot[12529]: time="2026-06-02T22:27:33+09:00" level=trace msg="scheduling prefetch in 149s" Jun 02 22:27:33 volumio go-librespot[12529]: time="2026-06-02T22:27:33+09:00" level=trace msg="emitting websocket event: metadata" Jun 02 22:27:33 volumio volumio[12339]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4P5ozkI1bxiGxA5rZ27jlO","name":"Bubble","artist_names":["STAYC"],"album_name":"TEENFRESH","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0205f3e920cfd3ae7fe9192149","position":0,"duration":179275,"release_date":"year:2023 month:8 day:16","track_number":1,"disc_number":1}} Jun 02 22:27:33 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Jun 02 22:27:33 volumio go-librespot[12529]: time="2026-06-02T22:27:33+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 22:27:33 volumio go-librespot[12529]: time="2026-06-02T22:27:33+09:00" level=trace msg="emitting websocket event: playing" Jun 02 22:27:33 volumio volumio[12339]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:7IUIgdUMzpoPQKX2MZrjqt","uri":"spotify:track:4P5ozkI1bxiGxA5rZ27jlO","resume":false,"play_origin":"playlist"}} Jun 02 22:27:33 volumio volumio[12339]: SPOTIFY: PUSH STATE SPOTIFY Jun 02 22:27:33 volumio volumio[12339]: SPOTIFY: {"status":"play","service":"spop","title":"Bubble","artist":"STAYC","album":"TEENFRESH","albumart":"https://i.scdn.co/image/ab67616d00001e0205f3e920cfd3ae7fe9192149","uri":"spotify:track:4P5ozkI1bxiGxA5rZ27jlO","trackType":"spotify","seek":0,"duration":179,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 02 22:27:33 volumio volumio[12339]: info: CoreCommandRouter::servicePushState Jun 02 22:27:33 volumio volumio[12339]: info: CoreStateMachine::pushState Jun 02 22:27:33 volumio volumio[12339]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 22:27:33 volumio volumio[12339]: info: CoreCommandRouter::volumioPushState Jun 02 22:27:33 volumio dbus-daemon[569]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.3166' (uid=0 pid=19867 comm="timedatectl show --property=NTPSynchronized --valu") Jun 02 22:27:33 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service... Jun 02 22:27:33 volumio go-librespot[12529]: time="2026-06-02T22:27:33+09:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:4P5ozkI1bxiGxA5rZ27jlO" Jun 02 22:27:34 volumio volumio[12339]: SPOTIFY: PUSH STATE SPOTIFY Jun 02 22:27:34 volumio volumio[12339]: SPOTIFY: {"status":"play","service":"spop","title":"Bubble","artist":"STAYC","album":"TEENFRESH","albumart":"https://i.scdn.co/image/ab67616d00001e0205f3e920cfd3ae7fe9192149","uri":"spotify:track:4P5ozkI1bxiGxA5rZ27jlO","trackType":"spotify","seek":0,"duration":179,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 02 22:27:34 volumio volumio[12339]: info: CoreCommandRouter::servicePushState Jun 02 22:27:34 volumio volumio[12339]: info: CoreStateMachine::pushState Jun 02 22:27:34 volumio volumio[12339]: info: CoreCommandRouter::volumioPushState Jun 02 22:27:34 volumio go-librespot[12529]: time="2026-06-02T22:27:34+09:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:4P5ozkI1bxiGxA5rZ27jlO" Jun 02 22:27:34 volumio dbus-daemon[569]: [system] Successfully activated service 'org.freedesktop.timedate1' Jun 02 22:27:34 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service. Jun 02 22:27:34 volumio setdatetime-helper.sh[19866]: Time is already synchronized. Jun 02 22:27:34 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Jun 02 22:27:34 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Jun 02 22:27:34 volumio go-librespot[12529]: time="2026-06-02T22:27:34+09:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:4P5ozkI1bxiGxA5rZ27jlO" Jun 02 22:27:39 volumio volumio[12339]: info: CoreCommandRouter::volumioPause Jun 02 22:27:39 volumio volumio[12339]: info: CoreStateMachine::pause Jun 02 22:27:39 volumio volumio[12339]: info: CoreStateMachine::stPlaybackTimer Jun 02 22:27:39 volumio volumio[12339]: info: CoreStateMachine::servicePause Jun 02 22:27:39 volumio volumio[12339]: info: CoreCommandRouter::servicePause Jun 02 22:27:39 volumio volumio[12339]: info: Spotify Received pause Jun 02 22:27:39 volumio volumio[12339]: SPOTIFY: SPOTIFY PAUSE Jun 02 22:27:39 volumio volumio[12339]: SPOTIFY: {"status":"play","title":"Bubble","artist":"STAYC","album":"TEENFRESH","albumart":"https://i.scdn.co/image/ab67616d00001e0205f3e920cfd3ae7fe9192149","uri":"spotify:track:4P5ozkI1bxiGxA5rZ27jlO","trackType":"spotify","codec":"ogg","seek":0,"duration":179,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":0,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"} Jun 02 22:27:39 volumio volumio[12339]: info: Sending Spotify command to local API: /player/pause Jun 02 22:27:39 volumio go-librespot[12529]: time="2026-06-02T22:27:39+09:00" level=debug msg="pause track at 5414ms" Jun 02 22:27:39 volumio go-librespot[12529]: time="2026-06-02T22:27:39+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 22:27:39 volumio go-librespot[12529]: time="2026-06-02T22:27:39+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 22:27:39 volumio go-librespot[12529]: time="2026-06-02T22:27:39+09:00" level=trace msg="emitting websocket event: paused" Jun 02 22:27:39 volumio volumio[12339]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:playlist:7IUIgdUMzpoPQKX2MZrjqt","uri":"spotify:track:4P5ozkI1bxiGxA5rZ27jlO","play_origin":"playlist"}} Jun 02 22:27:39 volumio volumio[12339]: SPOTIFY: PUSH STATE SPOTIFY Jun 02 22:27:39 volumio volumio[12339]: SPOTIFY: {"status":"pause","service":"spop","title":"Bubble","artist":"STAYC","album":"TEENFRESH","albumart":"https://i.scdn.co/image/ab67616d00001e0205f3e920cfd3ae7fe9192149","uri":"spotify:track:4P5ozkI1bxiGxA5rZ27jlO","trackType":"spotify","seek":6000,"duration":179,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 02 22:27:39 volumio volumio[12339]: info: CoreCommandRouter::servicePushState Jun 02 22:27:39 volumio volumio[12339]: info: CoreStateMachine::pushState Jun 02 22:27:39 volumio volumio[12339]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 22:27:39 volumio volumio[12339]: info: CoreCommandRouter::volumioPushState Jun 02 22:27:41 volumio volumio[12339]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jun 02 22:27:41 volumio volumio[12339]: info: In handleBrowseUri, curUri=spotify Jun 02 22:27:42 volumio volumio[12339]: info: New access token = BQAOLLwcgOZiSsiEFk7pP3U7u6K2TpGdamWiczjGctfvw66ryDri2DlLxuX8tC1wL45vcP8XVSrUsHUNI5m1_LqdX4Ai9kHRzIwMmL-KccB_ihwZI8NRoCu_Kha3NuGzvbRna7XXqMMAzg_CqB7rPnLeEEUsmXDEAuKg3KSEvMU9oSldOucEgS1jVKERVA5-osucO1KyIuB3EUvFYY4HCJoBFIuM6ab-o0yUR-CToIlkJXI5Y6wtNXKjyLjv6BEVUH5u5RVH7SnfOdkWJpTxLJA5XxU1-K6lriHaFMU0Z2o60bRVG7QHUSnzQc5MeA Jun 02 22:27:42 volumio volumio[12339]: info: New access token = BQDwFZLkZOrP6GnsuK3XILSszTHdQfyiU_4_iyFdJzWTXemBxLPQYDZWiXXg8fcv-jj-ytz72khOBsGQG1uWsZn0bXn3aHtxtmn1IWQZeWFnOTTKD9qgCWiU9M1LQrv0ikxHmKyzg3lcpExgqbjWzxvYMrLmD-JtWHX3cKDBDdHUhzpzmOd9mJrL5_pyPkuLSHWTDQh6LT3hA_vkehmPbnykpFy91zC3KsekcpyABSqatUi6RbDWI35eDl5p7LEm7W-TeD2iH0UA60mjtnjJPSnlDudjtfYG2AI6-smIYUqV4xkJyaPIAU73b8vrhw Jun 02 22:27:42 volumio volumio[12339]: info: New access token = BQCyUZrqIaktJVskHhkQZmgz9ivx1lDmXTixZhb6wfITQF6ErOey_IDpiu4YJikaRTMoHeRlqXRNjQk7e9Rv4feaSYdnLSncz1z7Pjt1AI3ETnM6x5Hc_pvqa_mZLEZ3YcI15jl7ikOoWVy_upC7aVfV6IidxNcb_AsQEKDXabiBp4-J2piTn3kbEpQlcNys2ZpQSVZI2nz8HkwaEPqYQ8fnoJ3l6ZP6D9wmHbxoL34uiH2Tn8uxmrX2235nMSL2FflkwMPYyKFn3VP7eZMABSNZrWzVXjNRnpwEkZctBRdDhCOTzEInJawntABVzg Jun 02 22:27:43 volumio volumio[12339]: info: Preload queue cleared Jun 02 22:27:43 volumio volumio[12339]: info: Preload queue cleared Jun 02 22:27:43 volumio volumio[12339]: info: Preload queue cleared Jun 02 22:27:43 volumio volumio[12339]: info: Preload queue cleared Jun 02 22:27:50 volumio go-librespot[12529]: time="2026-06-02T22:27:50+09:00" level=trace msg="sent dealer ping" Jun 02 22:27:50 volumio go-librespot[12529]: time="2026-06-02T22:27:50+09:00" level=trace msg="received dealer pong" Jun 02 22:27:59 volumio volumio[12339]: info: CoreCommandRouter::executeOnPlugin: youtube2 , handleBrowseUri Jun 02 22:27:59 volumio volumio[12339]: info: [youtube2-browse] browseUri: youtube2 Jun 02 22:27:59 volumio volumio[12339]: info: Preload queue cleared Jun 02 22:27:59 volumio volumio[12339]: info: Preload queue cleared Jun 02 22:28:04 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. Jun 02 22:28:08 volumio volumio[12339]: Searching all installed plugins Jun 02 22:28:08 volumio volumio[12339]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 22:28:08 volumio volumio[12339]: info: CoreCommandRouter::executeOnPlugin: , search Jun 02 22:28:08 volumio volumio[12339]: info: CoreCommandRouter::executeOnPlugin: mpd , search Jun 02 22:28:08 volumio volumio[12339]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search Jun 02 22:28:08 volumio volumio[12339]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Jun 02 22:28:08 volumio volumio[12339]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Jun 02 22:28:08 volumio volumio[12339]: info: CoreCommandRouter::executeOnPlugin: webradio , search Jun 02 22:28:08 volumio volumio[12339]: info: CoreCommandRouter::executeOnPlugin: youtube2 , search Jun 02 22:28:08 volumio volumio[12339]: info: CoreCommandRouter::executeOnPlugin: spop , search Jun 02 22:28:09 volumio volumio[12339]: Use XMLElement.setAttribute instead Jun 02 22:28:09 volumio volumio[12339]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 02 22:28:09 volumio volumio[12339]: TypeError: children[i].attr(...).value is not a function Jun 02 22:28:09 volumio volumio[12339]: at /volumio/app/plugins/music_service/webradio/index.js:956:46 Jun 02 22:28:09 volumio volumio[12339]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Jun 02 22:28:09 volumio volumio[12339]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 02 22:28:10 volumio sudo[19932]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-06-02 22:27' Jun 02 22:28:10 volumio sudo[19932]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 02 22:28:10 volumio sudo[19932]: pam_unix(sudo:session): session closed for user root Jun 02 22:28:11 volumio go-librespot[12529]: time="2026-06-02T22:28:11+09:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Jun 02 22:28:11 volumio volumio-remote-updater[598]: [2026-06-02 22:28:11] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jun 02 22:28:11 volumio volumio-remote-updater[598]: [2026-06-02 22:28:11] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jun 02 22:28:11 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jun 02 22:28:11 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jun 02 22:28:11 volumio systemd[1]: volumio.service: Consumed 11min 34.869s CPU time. Jun 02 22:28:11 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jun 02 22:28:11 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jun 02 22:28:11 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 3. Jun 02 22:28:11 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jun 02 22:28:11 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jun 02 22:28:11 volumio systemd[1]: volumio.service: Consumed 11min 34.869s CPU time. Jun 02 22:28:11 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jun 02 22:28:11 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jun 02 22:28:13 volumio volumio[19980]: info: ------------------------------------------- Jun 02 22:28:13 volumio volumio[19980]: info: ----- Volumio3 ---- Jun 02 22:28:13 volumio volumio[19980]: info: ------------------------------------------- Jun 02 22:28:13 volumio volumio[19980]: info: ----- System startup ---- Jun 02 22:28:13 volumio volumio[19980]: info: ------------------------------------------- Jun 02 22:28:14 volumio volumio[19980]: info: MYVOLUMIO Environment detected Jun 02 22:28:14 volumio volumio[19980]: info: Plugin folders cleanup Jun 02 22:28:14 volumio volumio[19980]: info: Scanning into folder /volumio/app/plugins/ Jun 02 22:28:14 volumio volumio[19980]: info: Scanning category audio_interface Jun 02 22:28:14 volumio volumio[19980]: info: Scanning category miscellanea Jun 02 22:28:14 volumio volumio[19980]: info: Scanning category music_service Jun 02 22:28:14 volumio volumio[19980]: info: Scanning category plugins.json Jun 02 22:28:14 volumio volumio[19980]: info: Scanning category system_controller Jun 02 22:28:14 volumio volumio[19980]: info: Scanning category user_interface Jun 02 22:28:14 volumio volumio[19980]: info: Scanning into folder /data/plugins/ Jun 02 22:28:14 volumio volumio[19980]: info: Scanning category music_service Jun 02 22:28:14 volumio volumio[19980]: info: Plugin folders cleanup completed Jun 02 22:28:14 volumio volumio[19980]: info: ------------------------------------------- Jun 02 22:28:14 volumio volumio[19980]: info: ----- Core plugins startup ---- Jun 02 22:28:14 volumio volumio[19980]: info: ------------------------------------------- Jun 02 22:28:14 volumio volumio[19980]: info: Loading plugins from folder /volumio/app/plugins/ Jun 02 22:28:14 volumio volumio[19980]: info: Adding plugin upnp to MyMusic Plugins Jun 02 22:28:14 volumio volumio[19980]: info: Adding plugin airplay_emulation to MyMusic Plugins Jun 02 22:28:14 volumio volumio[19980]: info: Adding plugin upnp_browser to MyMusic Plugins Jun 02 22:28:14 volumio volumio[19980]: info: Loading plugins from folder /data/plugins/ Jun 02 22:28:14 volumio volumio[19980]: info: Loading plugin "system"... Jun 02 22:28:15 volumio volumio[19980]: info: Loading plugin "appearance"... Jun 02 22:28:16 volumio volumio-remote-updater[598]: [2026-06-02 22:28:16] [connect] Successful connection Jun 02 22:28:16 volumio volumio[19980]: info: Loading plugin "network"... Jun 02 22:28:16 volumio volumio[19980]: info: Refreshing Cached IP Addresses Jun 02 22:28:16 volumio sudo[20008]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 02 22:28:16 volumio sudo[20008]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 02 22:28:16 volumio sudo[20008]: pam_unix(sudo:session): session closed for user root Jun 02 22:28:16 volumio sudo[20010]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 02 22:28:16 volumio sudo[20010]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 02 22:28:16 volumio volumio[19980]: info: Loading plugin "services"... Jun 02 22:28:16 volumio volumio[19980]: info: Loading plugin "alsa_controller"... Jun 02 22:28:16 volumio sudo[20019]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jun 02 22:28:16 volumio sudo[20010]: pam_unix(sudo:session): session closed for user root Jun 02 22:28:16 volumio sudo[20019]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 02 22:28:16 volumio sudo[20019]: pam_unix(sudo:session): session closed for user root Jun 02 22:28:16 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 02 22:28:16 volumio volumio[19980]: info: Loading plugin "wizard"... Jun 02 22:28:16 volumio volumio[19980]: info: Loading plugin "networkfs"... Jun 02 22:28:16 volumio volumio[19980]: info: Starting Udev Watcher for removable devices Jun 02 22:28:16 volumio volumio[19980]: info: Ignoring mount for partition: boot Jun 02 22:28:16 volumio volumio[19980]: info: Ignoring mount for partition: volumio Jun 02 22:28:16 volumio volumio[19980]: info: Ignoring mount for partition: volumio_data Jun 02 22:28:16 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 02 22:28:16 volumio volumio[19980]: info: Loading plugin "volumio_command_line_client"... Jun 02 22:28:16 volumio volumio[19980]: info: Loading plugin "upnp"... Jun 02 22:28:16 volumio volumio[19980]: info: [1780406896486] Starting Upmpd Daemon Jun 02 22:28:16 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 02 22:28:16 volumio volumio[19980]: info: Loading plugin "my_music"... Jun 02 22:28:16 volumio volumio[19980]: info: Loading plugin "mpd"... Jun 02 22:28:16 volumio volumio[19980]: info: Loading plugin "upnp_browser"... Jun 02 22:28:18 volumio volumio[19980]: info: Loading plugin "alarm-clock"... Jun 02 22:28:18 volumio volumio[19980]: info: Loading plugin "airplay_emulation"... Jun 02 22:28:18 volumio volumio[19980]: info: Starting Shairport Sync Jun 02 22:28:18 volumio volumio[19980]: info: Loading plugin "last_100"... Jun 02 22:28:18 volumio volumio[19980]: info: Loading plugin "webradio"... Jun 02 22:28:18 volumio volumio[19980]: info: Loading plugin "i2s_dacs"... Jun 02 22:28:18 volumio volumio[19980]: info: I2S DAC not set, start Auto-detection Jun 02 22:28:18 volumio volumio[19980]: info: Loading plugin "volumiodiscovery"... Jun 02 22:28:18 volumio volumio[19980]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 02 22:28:18 volumio volumio[19980]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 22:28:18 volumio volumio[19980]: *** WARNING *** For more information see Jun 02 22:28:18 volumio volumio[19980]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 02 22:28:18 volumio volumio[19980]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 22:28:18 volumio node[19980]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 02 22:28:18 volumio volumio[19980]: *** WARNING *** For more information see Jun 02 22:28:18 volumio node[19980]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 22:28:18 volumio node[19980]: *** WARNING *** For more information see Jun 02 22:28:18 volumio node[19980]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 02 22:28:18 volumio node[19980]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 22:28:18 volumio node[19980]: *** WARNING *** For more information see Jun 02 22:28:18 volumio volumio[19980]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 02 22:28:18 volumio volumio[19980]: info: Discovery: Started advertising with name: Volumio Jun 02 22:28:18 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 02 22:28:18 volumio volumio[19980]: info: Loading plugin "spop"... Jun 02 22:28:19 volumio volumio[19980]: info: Loading plugin "youtube2"... Jun 02 22:28:20 volumio go-librespot[12529]: time="2026-06-02T22:28:20+09:00" level=trace msg="sent dealer ping" Jun 02 22:28:20 volumio go-librespot[12529]: time="2026-06-02T22:28:20+09:00" level=trace msg="received dealer pong" Jun 02 22:28:20 volumio volumio[19980]: info: Loading plugin "outputs"... Jun 02 22:28:20 volumio volumio[19980]: info: Loading plugin "albumart"... Jun 02 22:28:20 volumio volumio[19980]: info: Plugin example_plugin is not enabled Jun 02 22:28:20 volumio volumio[19980]: info: Loading plugin "inputs"... Jun 02 22:28:20 volumio volumio[19980]: info: Loading plugin "updater_comm"... Jun 02 22:28:20 volumio volumio[19980]: info: Plugin mpdemulation is not enabled Jun 02 22:28:20 volumio volumio[19980]: info: Loading plugin "rest_api"... Jun 02 22:28:20 volumio volumio[19980]: info: Loading plugin "websocket"... Jun 02 22:28:20 volumio volumio[19980]: info: Starting Socket.io Server version 1.7.4 Jun 02 22:28:20 volumio volumio[19980]: info: Loading i18n strings for locale ko Jun 02 22:28:20 volumio volumio[19980]: Updating browse sources language Jun 02 22:28:20 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 22:28:20 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 02 22:28:20 volumio volumio[19980]: info: CoreCommandRouter::initPlayerControls Jun 02 22:28:20 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 22:28:20 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 22:28:20 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 22:28:20 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 22:28:20 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 22:28:20 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 22:28:20 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 22:28:20 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 22:28:20 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 02 22:28:20 volumio volumio[19980]: Express server listening on port 3000 Jun 02 22:28:20 volumio volumio[19980]: [Metrics] WebUI: 7s 519.76ms Jun 02 22:28:20 volumio volumio[19980]: info: CoreStateMachine::resetVolumioState Jun 02 22:28:20 volumio volumio[19980]: info: CoreStateMachine::getcurrentVolume Jun 02 22:28:20 volumio volumio[19980]: info: CoreCommandRouter::volumioRetrievevolume Jun 02 22:28:20 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 22:28:20 volumio volumio[19980]: info: Volumio Network Manager: Network status updated: 1 Jun 02 22:28:20 volumio volumio[19980]: Unable to parse: Jun 02 22:28:20 volumio volumio[19980]: Simple mixer control 'PCM',0 Jun 02 22:28:20 volumio volumio[19980]: Capabilities: pswitch pswitch-joined Jun 02 22:28:20 volumio volumio[19980]: Playback channels: Mono Jun 02 22:28:20 volumio volumio[19980]: Mono: Playback [on] Jun 02 22:28:20 volumio volumio[19980]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Jun 02 22:28:20 volumio volumio[19980]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Jun 02 22:28:20 volumio volumio[19980]: wlan0 Interface doesn't support scanning. Jun 02 22:28:20 volumio volumio[19980]: info: Cannot use regular scanning, forcing with ap-force Jun 02 22:28:21 volumio sudo[20064]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Jun 02 22:28:21 volumio sudo[20064]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 02 22:28:21 volumio sudo[20064]: pam_unix(sudo:session): session closed for user root Jun 02 22:28:21 volumio volumio[19980]: command failed: No such device (-19) Jun 02 22:28:21 volumio volumio[19980]: error: Cannot use fallback scanning method: Error: Command failed: /usr/bin/sudo /sbin/iw dev wlan0 scan ap-force Jun 02 22:28:21 volumio volumio[19980]: command failed: No such device (-19) Jun 02 22:28:21 volumio volumio[20047]: Forking 3 albumart workers Jun 02 22:28:21 volumio volumio[19980]: verbose: New Socket.io Connection to 192.168.219.115 from 192.168.219.102 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/146.0.0.0 Whale/4.37.378.12 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Jun 02 22:28:21 volumio volumio[19980]: Unable to parse: Jun 02 22:28:21 volumio volumio[19980]: Simple mixer control 'PCM',0 Jun 02 22:28:21 volumio volumio[19980]: Capabilities: pswitch pswitch-joined Jun 02 22:28:21 volumio volumio[19980]: Playback channels: Mono Jun 02 22:28:21 volumio volumio[19980]: Mono: Playback [on] Jun 02 22:28:21 volumio volumio[19980]: info: VolumeController:: Volume=undefined Mute =false Jun 02 22:28:21 volumio volumio[19980]: info: CoreStateMachine::pushState Jun 02 22:28:21 volumio volumio[19980]: info: CorePlayQueue::getTrack 0 Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::volumioPushState Jun 02 22:28:21 volumio volumio[19980]: info: CoreStateMachine::updateTrackBlock Jun 02 22:28:21 volumio volumio[19980]: info: CorePlayQueue::getTrackBlock Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::volumioRetrievevolume Jun 02 22:28:21 volumio volumio[19980]: verbose: New Socket.io Connection to 192.168.219.115 from 192.168.219.100 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/138.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 2 Jun 02 22:28:21 volumio volumio[19980]: info: Reloading queue from file Jun 02 22:28:21 volumio volumio[19980]: verbose: New Socket.io Connection to 192.168.219.115 from 192.168.219.102 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/146.0.0.0 Whale/4.37.378.12 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 3 Jun 02 22:28:21 volumio volumio[19980]: Unable to parse: Jun 02 22:28:21 volumio volumio[19980]: Simple mixer control 'PCM',0 Jun 02 22:28:21 volumio volumio[19980]: Capabilities: pswitch pswitch-joined Jun 02 22:28:21 volumio volumio[19980]: Playback channels: Mono Jun 02 22:28:21 volumio volumio[19980]: Mono: Playback [on] Jun 02 22:28:21 volumio volumio[19980]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Jun 02 22:28:21 volumio volumio[19980]: info: CoreStateMachine::setRepeat true single undefined Jun 02 22:28:21 volumio volumio[19980]: info: CoreStateMachine::pushState Jun 02 22:28:21 volumio volumio[19980]: info: CorePlayQueue::getTrack 0 Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::volumioPushState Jun 02 22:28:21 volumio volumio[19980]: info: CoreStateMachine::setRandom null Jun 02 22:28:21 volumio volumio[19980]: info: CoreStateMachine::pushState Jun 02 22:28:21 volumio volumio[19980]: info: CorePlayQueue::getTrack 0 Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::volumioPushState Jun 02 22:28:21 volumio volumio[19980]: info: Setting Device type: Raspberry PI Jun 02 22:28:21 volumio volumio[19980]: verbose: New Socket.io Connection to 192.168.219.115 from 192.168.219.100 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/138.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 4 Jun 02 22:28:21 volumio volumio[19980]: verbose: New Socket.io Connection to 192.168.219.115 from 192.168.219.102 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/146.0.0.0 Whale/4.37.378.12 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Jun 02 22:28:21 volumio volumio[19980]: Unable to parse: Jun 02 22:28:21 volumio volumio[19980]: Simple mixer control 'PCM',0 Jun 02 22:28:21 volumio volumio[19980]: Capabilities: pswitch pswitch-joined Jun 02 22:28:21 volumio volumio[19980]: Playback channels: Mono Jun 02 22:28:21 volumio volumio[19980]: Mono: Playback [on] Jun 02 22:28:21 volumio volumio[19980]: info: VolumeController:: Volume=undefined Mute =false Jun 02 22:28:21 volumio volumio[19980]: info: CoreStateMachine::pushState Jun 02 22:28:21 volumio volumio[19980]: info: CorePlayQueue::getTrack 0 Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::volumioPushState Jun 02 22:28:21 volumio volumio[19980]: info: Discovery: adding 08446652-bcba-4ff4-8bd6-527767cd76de Jun 02 22:28:21 volumio volumio[19980]: info: Discovery: Found device Volumio Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::volumioGetState Jun 02 22:28:21 volumio volumio[19980]: info: CorePlayQueue::getTrack 0 Jun 02 22:28:21 volumio volumio[19980]: info: Completed loading Core Plugins Jun 02 22:28:21 volumio volumio[19980]: info: Preparing to generate the ALSA configuration file Jun 02 22:28:21 volumio volumio[19980]: info: Discovery: this is already registered, 08446652-bcba-4ff4-8bd6-527767cd76de Jun 02 22:28:21 volumio volumio[19980]: info: Discovery: Found device Volumio Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::volumioGetState Jun 02 22:28:21 volumio volumio[19980]: info: CorePlayQueue::getTrack 0 Jun 02 22:28:21 volumio volumio[19980]: info: Asound.conf file unchanged, so no further update is needed Jun 02 22:28:21 volumio volumio[19980]: info: Output device has changed, restarting MPD Jun 02 22:28:21 volumio volumio[19980]: info: Output device has changed, restarting Shairport Sync Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 22:28:21 volumio sudo[20108]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 02 22:28:21 volumio sudo[20108]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 02 22:28:21 volumio sudo[20108]: pam_unix(sudo:session): session closed for user root Jun 02 22:28:21 volumio sudo[20110]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 02 22:28:21 volumio sudo[20110]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 02 22:28:21 volumio volumio[19980]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 02 22:28:21 volumio volumio[19980]: info: ___________ START PLUGINS ___________ Jun 02 22:28:21 volumio volumio[19980]: info: ControllerMpd::onStart: Initializing MPD Jun 02 22:28:21 volumio volumio[19980]: info: Creating MPD Configuration file Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 22:28:21 volumio volumio[19980]: info: [1780406901700] CoreMusicLibrary::Adding element 미디어 서버 Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 22:28:21 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 22:28:21 volumio sudo[20120]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 02 22:28:21 volumio sudo[20120]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 02 22:28:21 volumio volumio[19980]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 22:28:21 volumio systemd[1]: mpd.service: Deactivated successfully. Jun 02 22:28:21 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jun 02 22:28:21 volumio systemd[1]: mpd.service: Consumed 28.351s CPU time. Jun 02 22:28:21 volumio systemd[1]: mpd.socket: Deactivated successfully. Jun 02 22:28:21 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jun 02 22:28:21 volumio sudo[20118]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 02 22:28:21 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jun 02 22:28:21 volumio sudo[20118]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 02 22:28:21 volumio sudo[20118]: pam_unix(sudo:session): session closed for user root Jun 02 22:28:21 volumio volumio[19980]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 22:28:21 volumio volumio[19980]: info: [1780406901854] CoreMusicLibrary::Adding element Last_100 Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 22:28:21 volumio volumio[19980]: info: [1780406901862] CoreMusicLibrary::Adding element Webradio Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 22:28:21 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jun 02 22:28:21 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jun 02 22:28:21 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 02 22:28:21 volumio volumio[19980]: info: Initializing BBC Radios Jun 02 22:28:21 volumio systemd[1]: mpd.service: Deactivated successfully. Jun 02 22:28:21 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jun 02 22:28:21 volumio systemd[1]: mpd.socket: Deactivated successfully. Jun 02 22:28:21 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jun 02 22:28:21 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jun 02 22:28:21 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jun 02 22:28:21 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jun 02 22:28:22 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 02 22:28:22 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 22:28:22 volumio volumio[19980]: info: Creating Spotify config file Jun 02 22:28:22 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 22:28:22 volumio sudo[20143]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 02 22:28:22 volumio sudo[20143]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jun 02 22:28:22 volumio sudo[20143]: pam_unix(sudo:session): session closed for user root Jun 02 22:28:22 volumio volumio[20069]: Starting albumart workers Jun 02 22:28:22 volumio volumio[20071]: Starting albumart workers Jun 02 22:28:22 volumio volumio[19980]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 22:28:22 volumio volumio[19980]: info: [1780406902709] CoreMusicLibrary::Adding element YouTube2 Jun 02 22:28:22 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 22:28:22 volumio volumio[19980]: Cannot find translation for source YouTube2 Jun 02 22:28:22 volumio volumio[19980]: info: Volumio Calling Home Jun 02 22:28:22 volumio volumio[20070]: Starting albumart workers Jun 02 22:28:23 volumio volumio[19980]: verbose: New Socket.io Connection to 192.168.219.115 from 192.168.219.100 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/138.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Jun 02 22:28:23 volumio volumio[19980]: verbose: New Socket.io Connection to 192.168.219.115 from 192.168.219.102 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/146.0.0.0 Whale/4.37.378.12 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Jun 02 22:28:23 volumio volumio[19980]: info: MPD Permissions set Jun 02 22:28:23 volumio volumio[19980]: info: MPD Permissions set Jun 02 22:28:23 volumio volumio[19980]: info: Spotify config file written Jun 02 22:28:23 volumio volumio[19980]: info: CoreCommandRouter::volumioGetState Jun 02 22:28:23 volumio volumio[19980]: info: CorePlayQueue::getTrack 0 Jun 02 22:28:23 volumio volumio[19980]: Searching all installed plugins Jun 02 22:28:23 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 22:28:23 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: , search Jun 02 22:28:23 volumio volumio[19980]: info: CoreCommandRouter::executeOnPlugin: mpd , search Jun 02 22:28:23 volumio volumio[19980]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 02 22:28:23 volumio volumio[19980]: TypeError: Cannot read properties of undefined (reading 'then') Jun 02 22:28:23 volumio volumio[19980]: at ControllerMpd.search (/volumio/app/plugins/music_service/mpd/index.js:1583:17) Jun 02 22:28:23 volumio volumio[19980]: at CoreCommandRouter.executeOnPlugin (/volumio/app/index.js:1096:32) Jun 02 22:28:23 volumio volumio[19980]: at CoreMusicLibrary.searchOnPlugin (/volumio/app/musiclibrary.js:668:44) Jun 02 22:28:23 volumio volumio[19980]: at CoreMusicLibrary.search (/volumio/app/musiclibrary.js:455:27) Jun 02 22:28:23 volumio volumio[19980]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:485:44) Jun 02 22:28:23 volumio volumio[19980]: at Socket.emit (node:events:514:28) Jun 02 22:28:23 volumio volumio[19980]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Jun 02 22:28:23 volumio volumio[19980]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Jun 02 22:28:23 volumio volumio[19980]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 02 22:28:23 volumio sudo[20155]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 02 22:28:23 volumio sudo[20155]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 02 22:28:23 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jun 02 22:28:23 volumio systemd[1]: go-librespot-daemon.service: Killing process 12538 (go-librespot) with signal SIGKILL. Jun 02 22:28:23 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jun 02 22:28:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jun 02 22:28:23 volumio systemd[1]: go-librespot-daemon.service: Consumed 2min 45.421s CPU time. Jun 02 22:28:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jun 02 22:28:23 volumio go-librespot[20160]: go-librespot daemon starting... Jun 02 22:28:23 volumio sudo[20155]: pam_unix(sudo:session): session closed for user root Jun 02 22:28:23 volumio go-librespot[20169]: time="2026-06-02T22:28:23+09:00" level=info msg="running go-librespot 0.7.1" Jun 02 22:28:23 volumio go-librespot[20169]: time="2026-06-02T22:28:23+09:00" level=debug msg="app state loaded" Jun 02 22:28:23 volumio go-librespot[20169]: time="2026-06-02T22:28:23+09:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 02 22:28:23 volumio go-librespot[20169]: time="2026-06-02T22:28:23+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 02 22:28:23 volumio go-librespot[20169]: time="2026-06-02T22:28:23+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 02 22:28:23 volumio go-librespot[20169]: time="2026-06-02T22:28:23+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 02 22:28:23 volumio go-librespot[20169]: time="2026-06-02T22:28:23+09:00" level=info msg="zeroconf server listening on port 35941" Jun 02 22:28:23 volumio go-librespot[20169]: time="2026-06-02T22:28:23+09:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Jun 02 22:28:23 volumio go-librespot[20169]: time="2026-06-02T22:28:23+09:00" level=debug msg="obtained new client token: AAAWMHmtYpxUUqWT+yMjfwvCmZvYn+2O39d/4/q23I24uoWbSdZBexqmqXTuoKjmACAiwBbAVNB9MMyL8hIPgETILHDGuvQk7OZMror3GG/EthsECRotLrypKOj9LS79CmmItE3nD0p3Rfg54lQu7e3Bul14/z50DEZQl0bvl5d6Sn5pl8Qiky6dh5afflFW08VzbLfQHFgOrtNGjfff1RskDEPtepIPL0iH37YLfAbPo14Cv3XO+g==" Jun 02 22:28:24 volumio go-librespot[20169]: time="2026-06-02T22:28:24+09:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jun 02 22:28:24 volumio go-librespot[20169]: time="2026-06-02T22:28:24+09:00" level=debug msg="completed keyexchange" Jun 02 22:28:24 volumio go-librespot[20169]: time="2026-06-02T22:28:24+09:00" level=debug msg="completed challenge" Jun 02 22:28:24 volumio go-librespot[20169]: time="2026-06-02T22:28:24+09:00" level=info msg="authenticated AP" username="31************************3u" Jun 02 22:28:24 volumio go-librespot[20169]: time="2026-06-02T22:28:24+09:00" level=info msg="authenticated Login5" username="31************************3u" Jun 02 22:28:24 volumio go-librespot[20169]: time="2026-06-02T22:28:24+09:00" level=debug msg="initializing zeroconf session" username="31************************3u" Jun 02 22:28:24 volumio sudo[20200]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-06-02 22:27' Jun 02 22:28:24 volumio sudo[20200]: 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="4a70cb031e64a8e498efc3e29470650871ff7d54" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="04c18c158cc4bac70764c3360b25fcce0c69266a" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat May 31 04:09:10 UTC 2025" VOLUMIO_VERSION="4.005" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="f9bd4447a30d4b2c74b3880e7a50e48b"