May 22 20:07:13 volumiobw go-librespot[3256]: time="2025-05-22T20:07:13+07:00" level=trace msg="received accesspoint ping" May 22 20:07:13 volumiobw go-librespot[3256]: time="2025-05-22T20:07:13+07:00" level=trace msg="received accesspoint pong ack" May 22 20:07:13 volumiobw go-librespot[3256]: time="2025-05-22T20:07:13+07:00" level=trace msg="sent dealer ping" May 22 20:07:13 volumiobw go-librespot[3256]: time="2025-05-22T20:07:13+07:00" level=trace msg="received dealer pong" May 22 20:07:14 volumiobw volumio[1281]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 22 20:07:14 volumiobw volumio[1281]: info: In handleBrowseUri, curUri=spotify May 22 20:07:14 volumiobw volumio[1281]: info: Preload queue cleared May 22 20:07:14 volumiobw volumio[1281]: info: Preload queue cleared May 22 20:07:14 volumiobw volumio[1281]: info: Preload queue cleared May 22 20:07:14 volumiobw volumio[1281]: info: Preload queue cleared May 22 20:07:19 volumiobw systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... May 22 20:07:19 volumiobw dbus-daemon[874]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.55' (uid=0 pid=3472 comm="timedatectl show --property=NTPSynchronized --valu") May 22 20:07:19 volumiobw systemd[1]: Starting systemd-timedated.service - Time & Date Service... May 22 20:07:19 volumiobw dbus-daemon[874]: [system] Successfully activated service 'org.freedesktop.timedate1' May 22 20:07:19 volumiobw systemd[1]: Started systemd-timedated.service - Time & Date Service. May 22 20:07:19 volumiobw setdatetime-helper.sh[3471]: Time is not synchronized. Attempting to sync... May 22 20:07:19 volumiobw sudo[3480]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Thu, 22 May 2025 13:07:19 GMT#015' May 22 20:07:19 volumiobw sudo[3480]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) May 22 20:07:19 volumiobw setdatetime-helper.sh[3481]: Thu May 22 20:07:19 +07 2025 May 22 20:07:19 volumiobw sudo[3480]: pam_unix(sudo:session): session closed for user root May 22 20:07:19 volumiobw systemd-journald[430]: Time jumped backwards, rotating. May 22 20:07:19 volumiobw setdatetime-helper.sh[3471]: Time synchronized successfully. May 22 20:07:19 volumiobw systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. May 22 20:07:19 volumiobw systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. May 22 20:07:25 volumiobw volumio[1281]: Searching plugin music_service/spop May 22 20:07:25 volumiobw volumio[1281]: info: CoreCommandRouter::executeOnPlugin: spop , search May 22 20:07:26 volumiobw volumio[1281]: info: All search sources collected, pushing search results May 22 20:07:43 volumiobw go-librespot[3256]: time="2025-05-22T20:07:43+07:00" level=trace msg="sent dealer ping" May 22 20:07:43 volumiobw go-librespot[3256]: time="2025-05-22T20:07:43+07:00" level=trace msg="received dealer pong" May 22 20:07:48 volumiobw systemd[1]: systemd-timedated.service: Deactivated successfully. May 22 20:08:13 volumiobw go-librespot[3256]: time="2025-05-22T20:08:13+07:00" level=trace msg="sent dealer ping" May 22 20:08:13 volumiobw go-librespot[3256]: time="2025-05-22T20:08:13+07:00" level=trace msg="received dealer pong" May 22 20:08:28 volumiobw volumio[1281]: info: Preload queue cleared May 22 20:08:28 volumiobw volumio[1281]: info: CoreCommandRouter::volumioReplaceandPlayItems May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::ClearQueue May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::stop May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::serviceStop May 22 20:08:28 volumiobw volumio[1281]: info: Received STOP, but no service to execute it May 22 20:08:28 volumiobw volumio[1281]: info: CorePlayQueue::clearPlayQueue May 22 20:08:28 volumiobw volumio[1281]: info: CorePlayQueue::saveQueue May 22 20:08:28 volumiobw volumio[1281]: info: CoreCommandRouter::volumioPushQueue May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::addQueueItems May 22 20:08:28 volumiobw volumio[1281]: info: CorePlayQueue::addQueueItems May 22 20:08:28 volumiobw volumio[1281]: info: Preload queue cleared May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:2Wv45Oi6kW7KciaqESaTpW May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:2Wv45Oi6kW7KciaqESaTpW in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:2Wv45Oi6kW7KciaqESaTpW May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:7Jz7bghJS9IvRhiAggxEL9 May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:7Jz7bghJS9IvRhiAggxEL9 in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:7Jz7bghJS9IvRhiAggxEL9 May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:23XpwgxyD88eCmy8QeLGoa May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:23XpwgxyD88eCmy8QeLGoa in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:23XpwgxyD88eCmy8QeLGoa May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:2VK7NQeReNs2WSrDMGe3UB May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:2VK7NQeReNs2WSrDMGe3UB in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:2VK7NQeReNs2WSrDMGe3UB May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:6taFdTA4kUJp8ZrrbGdez3 May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:6taFdTA4kUJp8ZrrbGdez3 in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:6taFdTA4kUJp8ZrrbGdez3 May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:4bDINykue1HUVGkr9EDmIC May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:4bDINykue1HUVGkr9EDmIC in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:4bDINykue1HUVGkr9EDmIC May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:2EOtpfPJeiYZBfXwdjCU8m May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:2EOtpfPJeiYZBfXwdjCU8m in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:2EOtpfPJeiYZBfXwdjCU8m May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:5bOgBwcGie0yOV1yGQcIqw May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:5bOgBwcGie0yOV1yGQcIqw in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:5bOgBwcGie0yOV1yGQcIqw May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:4zvkt9eOHSSd8B0py1kh0Z May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:4zvkt9eOHSSd8B0py1kh0Z in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:4zvkt9eOHSSd8B0py1kh0Z May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:77y2yuF9HJt4gpZ1NvfLC2 May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:77y2yuF9HJt4gpZ1NvfLC2 in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:77y2yuF9HJt4gpZ1NvfLC2 May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:19uqRfluIodCOw7s6e4hcE May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:19uqRfluIodCOw7s6e4hcE in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:19uqRfluIodCOw7s6e4hcE May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:0krUeiPVZCxZ3wEFk9R5ws May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:0krUeiPVZCxZ3wEFk9R5ws in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:0krUeiPVZCxZ3wEFk9R5ws May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:4EGpwMGUuBR54MVINQZ5BG May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:4EGpwMGUuBR54MVINQZ5BG in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:4EGpwMGUuBR54MVINQZ5BG May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:2FyctfahP8681bb2toEY1F May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:2FyctfahP8681bb2toEY1F in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:2FyctfahP8681bb2toEY1F May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7Jz7bghJS9IvRhiAggxEL9","service":"spop","name":"ลมจ๋า","artist":"ศรัณย่า","album":"กล่อมกรุง 2 อาลัยรัก","type":"song","duration":191,"albumart":"https://i.scdn.co/image/ab67616d0000b27322f39b953f42c61b02e89e62","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2VK7NQeReNs2WSrDMGe3UB","service":"spop","name":"ลมจ๋า","artist":"สุชาติ ชวางกูร","album":"เพราะขอบฟ้ากว้าง","type":"song","duration":190,"albumart":"https://i.scdn.co/image/ab67616d0000b27383d63b0926c6f0750ec73c45","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2EOtpfPJeiYZBfXwdjCU8m","service":"spop","name":"ลมจ๋า","artist":"Sudhep Wongsakamhaeng","album":"สุเทพ แฟนคลับ CD1","type":"song","duration":175,"albumart":"https://i.scdn.co/image/ab67616d0000b273babd4f345d567d39cdd46d95","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:23XpwgxyD88eCmy8QeLGoa","service":"spop","name":"ลมจ๋า","artist":"Newery","album":"เบญจเทวกุล (Original Soundtrack)","type":"song","duration":190,"albumart":"https://i.scdn.co/image/ab67616d0000b27386afdc680371948c7f40224d","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2Wv45Oi6kW7KciaqESaTpW","service":"spop","name":"ลมจ๋า","artist":"Bird Thongchai","album":"BIRD 100 เพลงรักไม่รู้จบ 3 ชุด ภาษาใจ","type":"song","duration":234,"albumart":"https://i.scdn.co/image/ab67616d0000b2731572a0bda7135de652f1f45a","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5bOgBwcGie0yOV1yGQcIqw","service":"spop","name":"ลมจ๋า","artist":"ชรินทร์ นันทนาคร","album":"น้ำตาแสงใต้","type":"song","duration":173,"albumart":"https://i.scdn.co/image/8424139fe7fe0ae0322a23a928c636747df6770e","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4zvkt9eOHSSd8B0py1kh0Z","service":"spop","name":"ลมจ๋า","artist":"พัชรา แวงวรรณ","album":"๒๕๓๒ ชุดที่ ๑ ลั่นทม","type":"song","duration":214,"albumart":"https://i.scdn.co/image/ab67616d0000b27317d25d507fb2225dfb79570d","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6taFdTA4kUJp8ZrrbGdez3","service":"spop","name":"ขอดาว","artist":"Jofax","album":"Chick-Ka-Chick","type":"song","duration":278,"albumart":"https://i.scdn.co/image/ab67616d0000b273e96744f4111f5f78432491b8","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4bDINykue1HUVGkr9EDmIC","service":"spop","name":"ลมจ๋า","artist":"รอยัลสไปร์","album":"Love Memo, Vol. 1","type":"song","duration":203,"albumart":"https://i.scdn.co/image/ab67616d0000b273c4d0b63c073ef2730dbfba1e","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:77y2yuF9HJt4gpZ1NvfLC2","service":"spop","name":"ลมจ๋า","artist":"พรภิรมย์","album":"น้ำตาลาไทร","type":"song","duration":186,"albumart":"https://i.scdn.co/image/ab67616d0000b27315cb2353a51a346846c21cd6","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2FyctfahP8681bb2toEY1F","service":"spop","name":"ลมจ๋า","artist":"บุปผา สายชล","album":"ยมบาลเจ้าขา","type":"song","duration":162,"albumart":"https://i.scdn.co/image/ab67616d0000b273d3f53342ae9044f60927331a","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:19uqRfluIodCOw7s6e4hcE","service":"spop","name":"ลมจ๋า","artist":"สุนทร สุจริตฉันท์","album":"Best of Royal Spriles, Vol. 1","type":"song","duration":205,"albumart":"https://i.scdn.co/image/ab67616d0000b2737cfa623a154e8d71d310d79d","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0krUeiPVZCxZ3wEFk9R5ws","service":"spop","name":"ลมสวาท","artist":"Danupol Kaewkarn","album":"ที่สุดของที่สุด","type":"song","duration":192,"albumart":"https://i.scdn.co/image/ab67616d0000b273396bbd87b5c91f25ae538970","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4EGpwMGUuBR54MVINQZ5BG","service":"spop","name":"ลมจ๋า","artist":"หยาด นภาลัย","album":"ชุดที่ 8 คิดถึงพี่บ้างไหม","type":"song","duration":256,"albumart":"https://i.scdn.co/image/ab67616d0000b273b71ede5345fdf7d39fda368a","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw volumio[1281]: info: CoreCommandRouter::volumioPushQueue May 22 20:08:28 volumiobw volumio[1281]: info: CorePlayQueue::saveQueue May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::updateTrackBlock May 22 20:08:28 volumiobw volumio[1281]: info: CorePlayQueue::getTrackBlock May 22 20:08:28 volumiobw volumio[1281]: info: CoreCommandRouter::volumioPlay May 22 20:08:28 volumiobw volumio[1281]: verbose: UNSET VOLATILE: Service: undefined May 22 20:08:28 volumiobw volumio[1281]: ------------------------------------ BT MESSAGE: [FUNC] detachBluetooth May 22 20:08:28 volumiobw volumio[1281]: ------------------------------------ BT MESSAGE: [FUNC] btAudioOutput May 22 20:08:28 volumiobw volumio[1281]: ------------------------------------ BT MESSAGE: [dbus-next] Disabling Bluetooth Audio Output May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::play index 13 May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::setConsumeUpdateService undefined May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::addQueueItems May 22 20:08:28 volumiobw volumio[1281]: info: CorePlayQueue::addQueueItems May 22 20:08:28 volumiobw volumio[1281]: info: Preload queue cleared May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:4yxjuXm4nNHCa9XWp4qfaZ May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:4yxjuXm4nNHCa9XWp4qfaZ in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:4yxjuXm4nNHCa9XWp4qfaZ May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:5zYDGuiR6UcckknEFp678i May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:5zYDGuiR6UcckknEFp678i in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:5zYDGuiR6UcckknEFp678i May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:0EnuxAb6HgzDCjM2wIsRnD May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:0EnuxAb6HgzDCjM2wIsRnD in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:0EnuxAb6HgzDCjM2wIsRnD May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:2rvu7ytd4z6YbFASjw7QAR May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:2rvu7ytd4z6YbFASjw7QAR in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:2rvu7ytd4z6YbFASjw7QAR May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:4DGsczFQXesxDyCrMXJhhj May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:4DGsczFQXesxDyCrMXJhhj in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:4DGsczFQXesxDyCrMXJhhj May 22 20:08:28 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:3OokCIC3KZLfE4hv9CBjPW May 22 20:08:28 volumiobw volumio[1281]: info: Exploding uri spotify:track:3OokCIC3KZLfE4hv9CBjPW in service spop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: EXPLODING URI:spotify:track:3OokCIC3KZLfE4hv9CBjPW May 22 20:08:28 volumiobw volumio[1281]: ------------------------------------ BT MESSAGE: Bluetooth audio output disabled. May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::stop May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::setConsumeUpdateService undefined May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::resetVolumioState May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::getcurrentVolume May 22 20:08:28 volumiobw volumio[1281]: info: CoreCommandRouter::volumioRetrievevolume May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::play index undefined May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::setConsumeUpdateService undefined May 22 20:08:28 volumiobw volumio[1281]: info: CoreCommandRouter::volumioStop May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::stop May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::setConsumeUpdateService undefined May 22 20:08:28 volumiobw volumio[1281]: info: CorePlayQueue::getTrack 13 May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::startPlaybackTimer May 22 20:08:28 volumiobw volumio[1281]: info: CorePlayQueue::getTrack 13 May 22 20:08:28 volumiobw volumio[1281]: info: CoreCommandRouter::volumioGetVisibleSources May 22 20:08:28 volumiobw volumio[1281]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 22 20:08:28 volumiobw volumio[1281]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject May 22 20:08:28 volumiobw volumio[1281]: info: [1747919308516] ControllerSpotify::clearAddPlayTrack May 22 20:08:28 volumiobw volumio[1281]: info: Sending Spotify command with payload to local API: /player/play May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::pushState May 22 20:08:28 volumiobw volumio[1281]: info: CorePlayQueue::getTrack 13 May 22 20:08:28 volumiobw volumio[1281]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 22 20:08:28 volumiobw volumio[1281]: info: CoreCommandRouter::volumioPushState May 22 20:08:28 volumiobw volumio[1281]: info: MRS: Pushing multiroomSync output update for this device May 22 20:08:28 volumiobw volumio[1281]: info: MRS: Pushing multiroomSync output May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::updateTrackBlock May 22 20:08:28 volumiobw volumio[1281]: info: CorePlayQueue::getTrackBlock May 22 20:08:28 volumiobw volumio[1281]: info: CoreCommandRouter::volumioRetrievevolume May 22 20:08:28 volumiobw volumio[1281]: info: PeppyMeterBasic ---peppymeterbasic status stop May 22 20:08:28 volumiobw sudo[3601]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service May 22 20:08:28 volumiobw sudo[3601]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::pushState May 22 20:08:28 volumiobw volumio[1281]: info: CorePlayQueue::getTrack 13 May 22 20:08:28 volumiobw volumio[1281]: info: CoreCommandRouter::volumioPushState May 22 20:08:28 volumiobw volumio[1281]: info: MRS: Pushing multiroomSync output update for this device May 22 20:08:28 volumiobw volumio[1281]: info: MRS: Pushing multiroomSync output May 22 20:08:28 volumiobw volumio[1281]: info: PeppyMeterBasic ---peppymeterbasic status stop May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 May 22 20:08:28 volumiobw sudo[3605]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service May 22 20:08:28 volumiobw sudo[3605]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 22 20:08:28 volumiobw systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... May 22 20:08:28 volumiobw dbus-daemon[874]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.57' (uid=0 pid=3607 comm="timedatectl show --property=NTPSynchronized --valu") May 22 20:08:28 volumiobw sudo[3601]: pam_unix(sudo:session): session closed for user root May 22 20:08:28 volumiobw sudo[3605]: pam_unix(sudo:session): session closed for user root May 22 20:08:28 volumiobw volumio[1281]: info: peppymeterbasic Daemon Stop May 22 20:08:28 volumiobw volumio[1281]: info: peppymeterbasic Daemon Stop May 22 20:08:28 volumiobw systemd[1]: Starting systemd-timedated.service - Time & Date Service... May 22 20:08:28 volumiobw go-librespot[3256]: time="2025-05-22T20:08:28+07:00" level=debug msg="resolved context of track" uri="spotify:track:2FyctfahP8681bb2toEY1F" May 22 20:08:28 volumiobw go-librespot[3256]: time="2025-05-22T20:08:28+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2FyctfahP8681bb2toEY1F" May 22 20:08:28 volumiobw go-librespot[3256]: time="2025-05-22T20:08:28+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2FyctfahP8681bb2toEY1F" May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5zYDGuiR6UcckknEFp678i","service":"spop","name":"ลมจ๋า","artist":"รอยัลสไปร์ท","album":"LOVE MEMO 1","type":"song","duration":204,"albumart":"https://i.scdn.co/image/ab67616d0000b273dddd5b143ea28ed8d4d59f5e","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw dbus-daemon[874]: [system] Successfully activated service 'org.freedesktop.timedate1' May 22 20:08:28 volumiobw systemd[1]: Started systemd-timedated.service - Time & Date Service. May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3OokCIC3KZLfE4hv9CBjPW","service":"spop","name":"ลมหาย จางจาก","artist":"Greasy Cafe'","album":"ลมหาย จางจาก","type":"song","duration":270,"albumart":"https://i.scdn.co/image/ab67616d0000b27346d5630a526be36acdc38510","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw setdatetime-helper.sh[3603]: Time is not synchronized. Attempting to sync... May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0EnuxAb6HgzDCjM2wIsRnD","service":"spop","name":"ลมจ๋าลม","artist":"จินตนา สุขสถิตย์","album":"แม่ไม้เพลงไทย ชุด ลมจ๋าลม","type":"song","duration":171,"albumart":"https://i.scdn.co/image/ab67616d0000b2733d90465e89650b90ea1738a5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4yxjuXm4nNHCa9XWp4qfaZ","service":"spop","name":"ลมจ๋า","artist":"ศรัณย่า","album":"U-CHORUS PROJECT ดาวร้อยเดือน 2","type":"song","duration":194,"albumart":"https://i.scdn.co/image/ab67616d0000b2730bb16e2dd922bc27eac57548","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4DGsczFQXesxDyCrMXJhhj","service":"spop","name":"ลมจ๋าอย่าลืม","artist":"สลา คุณวุฒิ","album":"วง..จังหัน","type":"song","duration":207,"albumart":"https://i.scdn.co/image/ab67616d0000b2737b686b6affe5f6e8805214ad","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2rvu7ytd4z6YbFASjw7QAR","service":"spop","name":"ลมจ๋า","artist":"สามโทน","album":"สามใจ สามฮิต","type":"song","duration":232,"albumart":"https://i.scdn.co/image/ab67616d0000b273401a0221a924e04713e5de9b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 22 20:08:28 volumiobw volumio[1281]: info: CoreCommandRouter::volumioPushQueue May 22 20:08:28 volumiobw go-librespot[3256]: time="2025-05-22T20:08:28+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 22 20:08:28 volumiobw go-librespot[3256]: time="2025-05-22T20:08:28+07:00" level=trace msg="emitting websocket event: will_play" May 22 20:08:28 volumiobw volumio[1281]: info: CorePlayQueue::saveQueue May 22 20:08:28 volumiobw volumio[1281]: info: CoreStateMachine::updateTrackBlock May 22 20:08:28 volumiobw volumio[1281]: info: CorePlayQueue::getTrackBlock May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2FyctfahP8681bb2toEY1F","play_origin":"go-librespot"}} May 22 20:08:28 volumiobw volumio[1281]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2FyctfahP8681bb2toEY1F","play_origin":"go-librespot"}} May 22 20:08:28 volumiobw sudo[3615]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Thu, 22 May 2025 13:08:29 GMT#015' May 22 20:08:28 volumiobw sudo[3615]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) May 22 20:08:29 volumiobw setdatetime-helper.sh[3616]: Thu May 22 20:08:29 +07 2025 May 22 20:08:29 volumiobw sudo[3615]: pam_unix(sudo:session): session closed for user root May 22 20:08:29 volumiobw setdatetime-helper.sh[3603]: Time synchronized successfully. May 22 20:08:29 volumiobw systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. May 22 20:08:29 volumiobw systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. May 22 20:08:29 volumiobw go-librespot[3256]: time="2025-05-22T20:08:29+07:00" level=debug msg="selected format OGG_VORBIS_320 (9cfbbb6390c48c821f7844c5a303b5028fab4372)" uri="spotify:track:2FyctfahP8681bb2toEY1F" May 22 20:08:29 volumiobw go-librespot[3256]: time="2025-05-22T20:08:29+07:00" level=debug msg="requested aes key for file 9cfbbb6390c48c821f7844c5a303b5028fab4372, gid: 2FyctfahP8681bb2toEY1F" May 22 20:08:30 volumiobw volumio[1281]: info: Executing endpoint metavolumio May 22 20:08:30 volumiobw volumio[1281]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 22 20:08:30 volumiobw volumio[1281]: info: Executing endpoint metavolumio May 22 20:08:30 volumiobw volumio[1281]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 22 20:08:30 volumiobw volumio[1281]: info: Executing endpoint metavolumio May 22 20:08:30 volumiobw volumio[1281]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 22 20:08:30 volumiobw volumio[1281]: info: Executing endpoint metavolumio May 22 20:08:30 volumiobw volumio[1281]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 22 20:08:30 volumiobw volumio[1281]: info: Executing endpoint metavolumio May 22 20:08:30 volumiobw volumio[1281]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 22 20:08:30 volumiobw volumio[1281]: info: Executing endpoint metavolumio May 22 20:08:30 volumiobw volumio[1281]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 22 20:08:30 volumiobw go-librespot[3256]: time="2025-05-22T20:08:30+07:00" level=debug msg="fetched first chunk of 12, total size is 6172112 bytes" uri="spotify:track:2FyctfahP8681bb2toEY1F" May 22 20:08:30 volumiobw go-librespot[3256]: time="2025-05-22T20:08:30+07:00" level=debug msg="created new output device" May 22 20:08:30 volumiobw go-librespot[3256]: time="2025-05-22T20:08:30+07:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" May 22 20:08:30 volumiobw go-librespot[3256]: time="2025-05-22T20:08:30+07:00" level=info msg="loaded track \"ลมจ๋า\" (paused: false, position: 0ms, duration: 162664ms, prefetched: false)" uri="spotify:track:2FyctfahP8681bb2toEY1F" May 22 20:08:30 volumiobw go-librespot[3256]: time="2025-05-22T20:08:30+07:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:2FyctfahP8681bb2toEY1F" May 22 20:08:30 volumiobw go-librespot[3256]: time="2025-05-22T20:08:30+07:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:2FyctfahP8681bb2toEY1F" May 22 20:08:30 volumiobw go-librespot[3256]: time="2025-05-22T20:08:30+07:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:2FyctfahP8681bb2toEY1F" May 22 20:08:30 volumiobw go-librespot[3256]: time="2025-05-22T20:08:30+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 22 20:08:30 volumiobw go-librespot[3256]: time="2025-05-22T20:08:30+07:00" level=trace msg="scheduling prefetch in 133s" May 22 20:08:30 volumiobw go-librespot[3256]: time="2025-05-22T20:08:30+07:00" level=trace msg="emitting websocket event: metadata" May 22 20:08:30 volumiobw volumio[1281]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2FyctfahP8681bb2toEY1F","name":"ลมจ๋า","artist_names":["บุปผา สายชล"],"album_name":"ยมบาลเจ้าขา","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02d3f53342ae9044f60927331a","position":0,"duration":162664,"release_date":"year:2015 month:12 day:20","track_number":5,"disc_number":1}} May 22 20:08:30 volumiobw volumio[1281]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2FyctfahP8681bb2toEY1F","name":"ลมจ๋า","artist_names":["บุปผา สายชล"],"album_name":"ยมบาลเจ้าขา","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02d3f53342ae9044f60927331a","position":0,"duration":162664,"release_date":"year:2015 month:12 day:20","track_number":5,"disc_number":1}} May 22 20:08:31 volumiobw go-librespot[3256]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. May 22 20:08:31 volumiobw go-librespot[3255]: Aborted May 22 20:08:31 volumiobw volumio[1281]: info: Connection to go-librespot Websocket closed May 22 20:08:31 volumiobw volumio[1281]: info: Connection to go-librespot Websocket closed May 22 20:08:31 volumiobw systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a May 22 20:08:31 volumiobw systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 22 20:08:33 volumiobw volumio[1281]: error: Failed request for metavolumio API May 22 20:08:34 volumiobw volumio[1281]: info: Initializing connection to go-librespot Websocket May 22 20:08:34 volumiobw volumio[1281]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 22 20:08:34 volumiobw systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. May 22 20:08:34 volumiobw systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 22 20:08:34 volumiobw systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 22 20:08:34 volumiobw go-librespot[3619]: go-librespot daemon starting... May 22 20:08:34 volumiobw go-librespot[3620]: time="2025-05-22T20:08:34+07:00" level=info msg="running go-librespot 0.2.0" May 22 20:08:34 volumiobw go-librespot[3620]: time="2025-05-22T20:08:34+07:00" level=debug msg="app state loaded" May 22 20:08:34 volumiobw go-librespot[3620]: time="2025-05-22T20:08:34+07:00" level=info msg="api server listening on 127.0.0.1:9879" May 22 20:08:34 volumiobw go-librespot[3620]: time="2025-05-22T20:08:34+07: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-gew1.spotify.com:80]" May 22 20:08:34 volumiobw go-librespot[3620]: time="2025-05-22T20:08:34+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" May 22 20:08:34 volumiobw go-librespot[3620]: time="2025-05-22T20:08:34+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" May 22 20:08:34 volumiobw go-librespot[3620]: time="2025-05-22T20:08:34+07:00" level=info msg="zeroconf server listening on port 33549" May 22 20:08:34 volumiobw go-librespot[3620]: time="2025-05-22T20:08:34+07:00" level=debug msg="obtained new client token: AADPymTfN5QOlSyuaHdfhMztpqNAnu4PMFrczZ3dg2fZQoYpuspLAOB2s6vm/Z/5gwM6SAnpbDqjOIjrKf6pDGLH8lj73Nct2siepPpzcGTMzYIdfu++QSXu89UDwJZ8yUIzgT1how35937hMDt/UTSG3FhQgYvxNI837PRQxXtuxdtYxY2aCzFZkjKpHurZw1G6aOT9FS72mTVho+IZAValJ6+L2bPWUqCRGIXNWwQk2w5EuxJws5vi" May 22 20:08:34 volumiobw go-librespot[3620]: time="2025-05-22T20:08:34+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" May 22 20:08:34 volumiobw go-librespot[3620]: time="2025-05-22T20:08:34+07:00" level=debug msg="completed keyexchange" May 22 20:08:34 volumiobw go-librespot[3620]: time="2025-05-22T20:08:34+07:00" level=debug msg="completed challenge" May 22 20:08:35 volumiobw go-librespot[3620]: time="2025-05-22T20:08:35+07:00" level=info msg="authenticated AP as 31s6cmxtfatsybtjk7h5q2iw44sm" May 22 20:08:35 volumiobw go-librespot[3620]: time="2025-05-22T20:08:35+07:00" level=info msg="authenticated Login5 as 31s6cmxtfatsybtjk7h5q2iw44sm" May 22 20:08:35 volumiobw go-librespot[3620]: time="2025-05-22T20:08:35+07:00" level=debug msg="initializing zeroconf session, username: 31s6cmxtfatsybtjk7h5q2iw44sm" May 22 20:08:35 volumiobw go-librespot[3620]: time="2025-05-22T20:08:35+07:00" level=debug msg="dealer connection opened" May 22 20:08:35 volumiobw go-librespot[3620]: time="2025-05-22T20:08:35+07:00" level=trace msg="starting accesspoint recv loop" May 22 20:08:35 volumiobw go-librespot[3620]: time="2025-05-22T20:08:35+07:00" level=trace msg="starting dealer recv loop" May 22 20:08:35 volumiobw go-librespot[3620]: time="2025-05-22T20:08:35+07:00" level=trace msg="received accesspoint ping" May 22 20:08:35 volumiobw go-librespot[3620]: time="2025-05-22T20:08:35+07:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 22 20:08:35 volumiobw go-librespot[3620]: time="2025-05-22T20:08:35+07:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 22 20:08:35 volumiobw go-librespot[3620]: time="2025-05-22T20:08:35+07:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 22 20:08:35 volumiobw go-librespot[3620]: time="2025-05-22T20:08:35+07:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 22 20:08:35 volumiobw go-librespot[3620]: time="2025-05-22T20:08:35+07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 22 20:08:35 volumiobw go-librespot[3620]: time="2025-05-22T20:08:35+07:00" level=debug msg="received connection id: YzhmZDM2N2UtNTBkZi00Y2Y0LWI3YjktY2UwOWNhM2M4MjZiK2RlYWxlcit0Y3A6Ly8wYWM5NDgyNy5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArNTZCMDQ0RDVBODFGMDRBNEE4RTc3QzI4RDA2QkU3NEQ2ODI2MTBDNDYyRTNDNUMwOUE2M0JBNzQzQ0NFMTY0Nw==" May 22 20:08:35 volumiobw go-librespot[3620]: time="2025-05-22T20:08:35+07:00" level=trace msg="received accesspoint pong ack" May 22 20:08:35 volumiobw go-librespot[3620]: time="2025-05-22T20:08:35+07:00" level=debug msg="put connect state because NEW_DEVICE" May 22 20:08:37 volumiobw volumio[1281]: info: Initializing connection to go-librespot Websocket May 22 20:08:37 volumiobw volumio[1281]: info: Connection to go-librespot Websocket established May 22 20:08:37 volumiobw go-librespot[3620]: time="2025-05-22T20:08:37+07:00" level=debug msg="new websocket client" May 22 20:08:38 volumiobw volumio[1281]: info: Preload queue cleared May 22 20:08:38 volumiobw volumio[1281]: info: CoreCommandRouter::volumioReplaceandPlayItems May 22 20:08:38 volumiobw volumio[1281]: info: CoreStateMachine::ClearQueue May 22 20:08:38 volumiobw volumio[1281]: info: CoreStateMachine::stop May 22 20:08:38 volumiobw volumio[1281]: info: CoreStateMachine::setConsumeUpdateService undefined May 22 20:08:38 volumiobw volumio[1281]: info: CorePlayQueue::clearPlayQueue May 22 20:08:38 volumiobw volumio[1281]: info: CorePlayQueue::saveQueue May 22 20:08:38 volumiobw volumio[1281]: info: CoreCommandRouter::volumioPushQueue May 22 20:08:38 volumiobw volumio[1281]: info: CoreStateMachine::addQueueItems May 22 20:08:38 volumiobw volumio[1281]: info: CorePlayQueue::addQueueItems May 22 20:08:38 volumiobw volumio[1281]: info: Preload queue cleared May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:2Wv45Oi6kW7KciaqESaTpW May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:2Wv45Oi6kW7KciaqESaTpW May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:7Jz7bghJS9IvRhiAggxEL9 May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:7Jz7bghJS9IvRhiAggxEL9 May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:23XpwgxyD88eCmy8QeLGoa May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:23XpwgxyD88eCmy8QeLGoa May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:2VK7NQeReNs2WSrDMGe3UB May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:2VK7NQeReNs2WSrDMGe3UB May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:6taFdTA4kUJp8ZrrbGdez3 May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:6taFdTA4kUJp8ZrrbGdez3 May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:4bDINykue1HUVGkr9EDmIC May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:4bDINykue1HUVGkr9EDmIC May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:2EOtpfPJeiYZBfXwdjCU8m May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:2EOtpfPJeiYZBfXwdjCU8m May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:5bOgBwcGie0yOV1yGQcIqw May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:5bOgBwcGie0yOV1yGQcIqw May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:4zvkt9eOHSSd8B0py1kh0Z May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:4zvkt9eOHSSd8B0py1kh0Z May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:77y2yuF9HJt4gpZ1NvfLC2 May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:77y2yuF9HJt4gpZ1NvfLC2 May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:19uqRfluIodCOw7s6e4hcE May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:19uqRfluIodCOw7s6e4hcE May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:0krUeiPVZCxZ3wEFk9R5ws May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:0krUeiPVZCxZ3wEFk9R5ws May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:4EGpwMGUuBR54MVINQZ5BG May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:4EGpwMGUuBR54MVINQZ5BG May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:2FyctfahP8681bb2toEY1F May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:2FyctfahP8681bb2toEY1F May 22 20:08:38 volumiobw volumio[1281]: info: CoreCommandRouter::volumioPushQueue May 22 20:08:38 volumiobw volumio[1281]: info: CorePlayQueue::saveQueue May 22 20:08:38 volumiobw volumio[1281]: info: CoreStateMachine::updateTrackBlock May 22 20:08:38 volumiobw volumio[1281]: info: CorePlayQueue::getTrackBlock May 22 20:08:38 volumiobw volumio[1281]: info: CoreCommandRouter::volumioPlay May 22 20:08:38 volumiobw volumio[1281]: info: CoreStateMachine::play index 13 May 22 20:08:38 volumiobw volumio[1281]: info: CoreStateMachine::setConsumeUpdateService undefined May 22 20:08:38 volumiobw volumio[1281]: info: CoreStateMachine::addQueueItems May 22 20:08:38 volumiobw volumio[1281]: info: CorePlayQueue::addQueueItems May 22 20:08:38 volumiobw volumio[1281]: info: Preload queue cleared May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:4yxjuXm4nNHCa9XWp4qfaZ May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:4yxjuXm4nNHCa9XWp4qfaZ May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:5zYDGuiR6UcckknEFp678i May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:5zYDGuiR6UcckknEFp678i May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:0EnuxAb6HgzDCjM2wIsRnD May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:0EnuxAb6HgzDCjM2wIsRnD May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:2rvu7ytd4z6YbFASjw7QAR May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:2rvu7ytd4z6YbFASjw7QAR May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:4DGsczFQXesxDyCrMXJhhj May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:4DGsczFQXesxDyCrMXJhhj May 22 20:08:38 volumiobw volumio[1281]: info: Adding Item to queue: spotify:track:3OokCIC3KZLfE4hv9CBjPW May 22 20:08:38 volumiobw volumio[1281]: info: Using cached record of: spotify:track:3OokCIC3KZLfE4hv9CBjPW May 22 20:08:38 volumiobw volumio[1281]: info: CoreStateMachine::stop May 22 20:08:38 volumiobw volumio[1281]: info: CoreStateMachine::setConsumeUpdateService undefined May 22 20:08:38 volumiobw volumio[1281]: info: CoreCommandRouter::volumioPushQueue May 22 20:08:38 volumiobw volumio[1281]: info: CorePlayQueue::saveQueue May 22 20:08:38 volumiobw volumio[1281]: info: CoreStateMachine::play index undefined May 22 20:08:38 volumiobw volumio[1281]: info: CoreStateMachine::setConsumeUpdateService undefined May 22 20:08:38 volumiobw volumio[1281]: info: CoreStateMachine::updateTrackBlock May 22 20:08:38 volumiobw volumio[1281]: info: CorePlayQueue::getTrackBlock May 22 20:08:38 volumiobw volumio[1281]: info: CorePlayQueue::getTrack 13 May 22 20:08:38 volumiobw volumio[1281]: info: CoreStateMachine::startPlaybackTimer May 22 20:08:38 volumiobw volumio[1281]: info: CorePlayQueue::getTrack 13 May 22 20:08:38 volumiobw volumio[1281]: info: [1747919318347] ControllerSpotify::clearAddPlayTrack May 22 20:08:38 volumiobw volumio[1281]: info: Sending Spotify command with payload to local API: /player/play May 22 20:08:38 volumiobw go-librespot[3620]: time="2025-05-22T20:08:38+07:00" level=debug msg="resolved context of track" uri="spotify:track:2FyctfahP8681bb2toEY1F" May 22 20:08:38 volumiobw go-librespot[3620]: time="2025-05-22T20:08:38+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2FyctfahP8681bb2toEY1F" May 22 20:08:38 volumiobw go-librespot[3620]: time="2025-05-22T20:08:38+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2FyctfahP8681bb2toEY1F" May 22 20:08:38 volumiobw go-librespot[3620]: time="2025-05-22T20:08:38+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 22 20:08:38 volumiobw go-librespot[3620]: time="2025-05-22T20:08:38+07:00" level=trace msg="emitting websocket event: will_play" May 22 20:08:38 volumiobw volumio[1281]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2FyctfahP8681bb2toEY1F","play_origin":"go-librespot"}} May 22 20:08:38 volumiobw go-librespot[3620]: time="2025-05-22T20:08:38+07:00" level=debug msg="selected format OGG_VORBIS_320 (9cfbbb6390c48c821f7844c5a303b5028fab4372)" uri="spotify:track:2FyctfahP8681bb2toEY1F" May 22 20:08:38 volumiobw go-librespot[3620]: time="2025-05-22T20:08:38+07:00" level=debug msg="requested aes key for file 9cfbbb6390c48c821f7844c5a303b5028fab4372, gid: 2FyctfahP8681bb2toEY1F" May 22 20:08:39 volumiobw go-librespot[3620]: time="2025-05-22T20:08:39+07:00" level=debug msg="fetched first chunk of 12, total size is 6172112 bytes" uri="spotify:track:2FyctfahP8681bb2toEY1F" May 22 20:08:39 volumiobw go-librespot[3620]: time="2025-05-22T20:08:39+07:00" level=debug msg="created new output device" May 22 20:08:39 volumiobw go-librespot[3620]: time="2025-05-22T20:08:39+07:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" May 22 20:08:39 volumiobw go-librespot[3620]: time="2025-05-22T20:08:39+07:00" level=info msg="loaded track \"ลมจ๋า\" (paused: false, position: 0ms, duration: 162664ms, prefetched: false)" uri="spotify:track:2FyctfahP8681bb2toEY1F" May 22 20:08:39 volumiobw go-librespot[3620]: time="2025-05-22T20:08:39+07:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:2FyctfahP8681bb2toEY1F" May 22 20:08:39 volumiobw go-librespot[3620]: time="2025-05-22T20:08:39+07:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:2FyctfahP8681bb2toEY1F" May 22 20:08:39 volumiobw go-librespot[3620]: time="2025-05-22T20:08:39+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 22 20:08:39 volumiobw go-librespot[3620]: time="2025-05-22T20:08:39+07:00" level=trace msg="scheduling prefetch in 133s" May 22 20:08:39 volumiobw go-librespot[3620]: time="2025-05-22T20:08:39+07:00" level=trace msg="emitting websocket event: metadata" May 22 20:08:39 volumiobw volumio[1281]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2FyctfahP8681bb2toEY1F","name":"ลมจ๋า","artist_names":["บุปผา สายชล"],"album_name":"ยมบาลเจ้าขา","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02d3f53342ae9044f60927331a","position":0,"duration":162664,"release_date":"year:2015 month:12 day:20","track_number":5,"disc_number":1}} May 22 20:08:39 volumiobw go-librespot[3620]: time="2025-05-22T20:08:39+07:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:2FyctfahP8681bb2toEY1F" May 22 20:08:39 volumiobw go-librespot[3620]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. May 22 20:08:39 volumiobw go-librespot[3619]: Aborted May 22 20:08:39 volumiobw volumio[1281]: info: Connection to go-librespot Websocket closed May 22 20:08:39 volumiobw systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a May 22 20:08:39 volumiobw systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 22 20:08:40 volumiobw volumio[1281]: info: Getting Spotify volume May 22 20:08:40 volumiobw volumio[1281]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 22 20:08:40 volumiobw volumio[1281]: Error: connect ECONNREFUSED 127.0.0.1:9879 May 22 20:08:40 volumiobw volumio[1281]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { May 22 20:08:40 volumiobw volumio[1281]: errno: -111, May 22 20:08:40 volumiobw volumio[1281]: code: 'ECONNREFUSED', May 22 20:08:40 volumiobw volumio[1281]: syscall: 'connect', May 22 20:08:40 volumiobw volumio[1281]: address: '127.0.0.1', May 22 20:08:40 volumiobw volumio[1281]: port: 9879, May 22 20:08:40 volumiobw volumio[1281]: response: undefined May 22 20:08:40 volumiobw volumio[1281]: } May 22 20:08:40 volumiobw volumio[1281]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 22 20:08:40 volumiobw sudo[3658]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-05-22 20:07' May 22 20:08:40 volumiobw sudo[3658]: 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="26d819930af572ef184e636a18ef1127de78f391" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed May 21 13:47:54 UTC 2025" VOLUMIO_VERSION="0.068" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="82c7b61aa1619bd495d6c4f648975de8"