-- Logs begin at Tue 2025-05-27 13:46:56 -07, end at Tue 2025-05-27 14:41:44 -07. -- May 27 14:40:03 volumio volumio[998]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 27 14:40:03 volumio volumio[998]: info: In handleBrowseUri, curUri=spotify:album:1R9y7ylS5egktBausRtuvV May 27 14:40:04 volumio volumio[998]: info: Preload queue cleared May 27 14:40:04 volumio volumio[998]: info: Preloading song: spotify:track:4sWZOj02iWOTHijL4DKEDy May 27 14:40:04 volumio volumio[998]: info: Preloading song: spotify:track:5mOeGiZISBUnYvxQEOoD2r May 27 14:40:04 volumio volumio[998]: info: Preloading song: spotify:track:69hpvEsYdMV36sipEavyIT May 27 14:40:04 volumio volumio[998]: info: Preloading song: spotify:track:5yBA0gVMaug8E01GSQdJCC May 27 14:40:04 volumio volumio[998]: info: Preloading song: spotify:track:45492F9vlxyWTS7bCz23vN May 27 14:40:04 volumio volumio[998]: info: Preloading song: spotify:track:0TFkcXdc7gB81kqfHMFgJD May 27 14:40:04 volumio volumio[998]: info: Preloading song: spotify:track:5m7E01gHsMYn0yRIuqALQO May 27 14:40:04 volumio volumio[998]: info: Preloading song: spotify:track:5wFZ2DZeeUzaXWUsBFIF46 May 27 14:40:04 volumio volumio[998]: info: Preloading song: spotify:track:0RjLEfhISRNgzKOoQ23mSZ May 27 14:40:04 volumio volumio[998]: info: Preloading song: spotify:track:0vBxoBYyxAFbk85kCA7wY8 May 27 14:40:04 volumio volumio[998]: info: Preloading song: spotify:track:4WuVSEKikU6ER0i5suO6qR May 27 14:40:04 volumio volumio[998]: info: Preloading song: spotify:track:44Q1YUwzMudaJxmKK7w0rN May 27 14:40:04 volumio volumio[998]: info: Exploding uri spotify:track:4sWZOj02iWOTHijL4DKEDy in service spop May 27 14:40:04 volumio volumio[998]: SPOTIFY: EXPLODING URI:spotify:track:4sWZOj02iWOTHijL4DKEDy May 27 14:40:04 volumio volumio[998]: info: Exploding uri spotify:track:5mOeGiZISBUnYvxQEOoD2r in service spop May 27 14:40:04 volumio volumio[998]: SPOTIFY: EXPLODING URI:spotify:track:5mOeGiZISBUnYvxQEOoD2r May 27 14:40:04 volumio volumio[998]: info: Exploding uri spotify:track:69hpvEsYdMV36sipEavyIT in service spop May 27 14:40:04 volumio volumio[998]: SPOTIFY: EXPLODING URI:spotify:track:69hpvEsYdMV36sipEavyIT May 27 14:40:04 volumio volumio[998]: info: Exploding uri spotify:track:5yBA0gVMaug8E01GSQdJCC in service spop May 27 14:40:04 volumio volumio[998]: SPOTIFY: EXPLODING URI:spotify:track:5yBA0gVMaug8E01GSQdJCC May 27 14:40:04 volumio volumio[998]: info: Exploding uri spotify:track:45492F9vlxyWTS7bCz23vN in service spop May 27 14:40:04 volumio volumio[998]: SPOTIFY: EXPLODING URI:spotify:track:45492F9vlxyWTS7bCz23vN May 27 14:40:04 volumio volumio[998]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","service":"spop","name":"Chuyện buồn ngày xuân","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","type":"song","duration":310,"albumart":"https://i.scdn.co/image/ab67616d0000b273dd0ae6989e96ce41da72741d","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:40:04 volumio volumio[998]: info: Exploding uri spotify:track:0TFkcXdc7gB81kqfHMFgJD in service spop May 27 14:40:04 volumio volumio[998]: SPOTIFY: EXPLODING URI:spotify:track:0TFkcXdc7gB81kqfHMFgJD May 27 14:40:04 volumio volumio[998]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5mOeGiZISBUnYvxQEOoD2r","service":"spop","name":"Ai khổ vì ai","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","type":"song","duration":327,"albumart":"https://i.scdn.co/image/ab67616d0000b273dd0ae6989e96ce41da72741d","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:40:04 volumio volumio[998]: info: Exploding uri spotify:track:5m7E01gHsMYn0yRIuqALQO in service spop May 27 14:40:04 volumio volumio[998]: SPOTIFY: EXPLODING URI:spotify:track:5m7E01gHsMYn0yRIuqALQO May 27 14:40:04 volumio volumio[998]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:69hpvEsYdMV36sipEavyIT","service":"spop","name":"Mùa đông về chưa em","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","type":"song","duration":294,"albumart":"https://i.scdn.co/image/ab67616d0000b273dd0ae6989e96ce41da72741d","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:40:04 volumio volumio[998]: info: Exploding uri spotify:track:5wFZ2DZeeUzaXWUsBFIF46 in service spop May 27 14:40:04 volumio volumio[998]: SPOTIFY: EXPLODING URI:spotify:track:5wFZ2DZeeUzaXWUsBFIF46 May 27 14:40:05 volumio volumio[998]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5yBA0gVMaug8E01GSQdJCC","service":"spop","name":"Nhớ người thương không","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","type":"song","duration":269,"albumart":"https://i.scdn.co/image/ab67616d0000b273dd0ae6989e96ce41da72741d","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:40:05 volumio volumio[998]: info: Exploding uri spotify:track:0RjLEfhISRNgzKOoQ23mSZ in service spop May 27 14:40:05 volumio volumio[998]: SPOTIFY: EXPLODING URI:spotify:track:0RjLEfhISRNgzKOoQ23mSZ May 27 14:40:05 volumio volumio[998]: info: Exploding uri spotify:track:0vBxoBYyxAFbk85kCA7wY8 in service spop May 27 14:40:05 volumio volumio[998]: SPOTIFY: EXPLODING URI:spotify:track:0vBxoBYyxAFbk85kCA7wY8 May 27 14:40:05 volumio volumio[998]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0TFkcXdc7gB81kqfHMFgJD","service":"spop","name":"Hoa tím ngày xưa","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","type":"song","duration":285,"albumart":"https://i.scdn.co/image/ab67616d0000b273dd0ae6989e96ce41da72741d","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:40:05 volumio volumio[998]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:45492F9vlxyWTS7bCz23vN","service":"spop","name":"Bài hát này cho anh","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","type":"song","duration":289,"albumart":"https://i.scdn.co/image/ab67616d0000b273dd0ae6989e96ce41da72741d","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:40:05 volumio volumio[998]: info: Exploding uri spotify:track:4WuVSEKikU6ER0i5suO6qR in service spop May 27 14:40:05 volumio volumio[998]: SPOTIFY: EXPLODING URI:spotify:track:4WuVSEKikU6ER0i5suO6qR May 27 14:40:05 volumio volumio[998]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5m7E01gHsMYn0yRIuqALQO","service":"spop","name":"Tâm sự với anh","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","type":"song","duration":317,"albumart":"https://i.scdn.co/image/ab67616d0000b273dd0ae6989e96ce41da72741d","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:40:05 volumio volumio[998]: info: Exploding uri spotify:track:44Q1YUwzMudaJxmKK7w0rN in service spop May 27 14:40:05 volumio volumio[998]: SPOTIFY: EXPLODING URI:spotify:track:44Q1YUwzMudaJxmKK7w0rN May 27 14:40:05 volumio volumio[998]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5wFZ2DZeeUzaXWUsBFIF46","service":"spop","name":"Một chuyến bay đêm","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","type":"song","duration":321,"albumart":"https://i.scdn.co/image/ab67616d0000b273dd0ae6989e96ce41da72741d","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:40:05 volumio volumio[998]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0RjLEfhISRNgzKOoQ23mSZ","service":"spop","name":"Xuôi giòng","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","type":"song","duration":283,"albumart":"https://i.scdn.co/image/ab67616d0000b273dd0ae6989e96ce41da72741d","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:40:05 volumio volumio[998]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0vBxoBYyxAFbk85kCA7wY8","service":"spop","name":"Kể chuyện trong đêm","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","type":"song","duration":279,"albumart":"https://i.scdn.co/image/ab67616d0000b273dd0ae6989e96ce41da72741d","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:40:05 volumio volumio[998]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4WuVSEKikU6ER0i5suO6qR","service":"spop","name":"Đọc tin trên báo","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","type":"song","duration":265,"albumart":"https://i.scdn.co/image/ab67616d0000b273dd0ae6989e96ce41da72741d","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:40:05 volumio volumio[998]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:44Q1YUwzMudaJxmKK7w0rN","service":"spop","name":"Ngày mai không có anh","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","type":"song","duration":331,"albumart":"https://i.scdn.co/image/ab67616d0000b273dd0ae6989e96ce41da72741d","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:40:06 volumio volumio[998]: info: Preload queue cleared May 27 14:40:06 volumio volumio[998]: info: CoreCommandRouter::volumioReplaceandPlayItems May 27 14:40:06 volumio volumio[998]: info: CoreStateMachine::ClearQueue May 27 14:40:06 volumio volumio[998]: info: CoreStateMachine::stop May 27 14:40:06 volumio volumio[998]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 14:40:06 volumio volumio[998]: info: CorePlayQueue::clearPlayQueue May 27 14:40:06 volumio volumio[998]: info: CorePlayQueue::saveQueue May 27 14:40:06 volumio volumio[998]: info: CoreCommandRouter::volumioPushQueue May 27 14:40:06 volumio volumio[998]: info: CoreStateMachine::addQueueItems May 27 14:40:06 volumio volumio[998]: info: CorePlayQueue::addQueueItems May 27 14:40:06 volumio volumio[998]: info: Preload queue cleared May 27 14:40:06 volumio volumio[998]: info: Adding Item to queue: spotify:track:4sWZOj02iWOTHijL4DKEDy May 27 14:40:06 volumio volumio[998]: info: Using cached record of: spotify:track:4sWZOj02iWOTHijL4DKEDy May 27 14:40:06 volumio volumio[998]: info: CoreCommandRouter::volumioPushQueue May 27 14:40:06 volumio volumio[998]: info: CorePlayQueue::saveQueue May 27 14:40:06 volumio volumio[998]: info: CoreStateMachine::updateTrackBlock May 27 14:40:06 volumio volumio[998]: info: CorePlayQueue::getTrackBlock May 27 14:40:06 volumio volumio[998]: info: CoreCommandRouter::volumioPlay May 27 14:40:06 volumio volumio[998]: info: CoreStateMachine::play index 0 May 27 14:40:06 volumio volumio[998]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 14:40:06 volumio volumio[998]: info: CoreStateMachine::addQueueItems May 27 14:40:06 volumio volumio[998]: info: CorePlayQueue::addQueueItems May 27 14:40:06 volumio volumio[998]: info: Preload queue cleared May 27 14:40:06 volumio volumio[998]: info: Adding Item to queue: spotify:track:5mOeGiZISBUnYvxQEOoD2r May 27 14:40:06 volumio volumio[998]: info: Using cached record of: spotify:track:5mOeGiZISBUnYvxQEOoD2r May 27 14:40:06 volumio volumio[998]: info: Adding Item to queue: spotify:track:69hpvEsYdMV36sipEavyIT May 27 14:40:06 volumio volumio[998]: info: Using cached record of: spotify:track:69hpvEsYdMV36sipEavyIT May 27 14:40:06 volumio volumio[998]: info: Adding Item to queue: spotify:track:5yBA0gVMaug8E01GSQdJCC May 27 14:40:06 volumio volumio[998]: info: Using cached record of: spotify:track:5yBA0gVMaug8E01GSQdJCC May 27 14:40:06 volumio volumio[998]: info: Adding Item to queue: spotify:track:45492F9vlxyWTS7bCz23vN May 27 14:40:06 volumio volumio[998]: info: Using cached record of: spotify:track:45492F9vlxyWTS7bCz23vN May 27 14:40:06 volumio volumio[998]: info: Adding Item to queue: spotify:track:0TFkcXdc7gB81kqfHMFgJD May 27 14:40:06 volumio volumio[998]: info: Using cached record of: spotify:track:0TFkcXdc7gB81kqfHMFgJD May 27 14:40:06 volumio volumio[998]: info: Adding Item to queue: spotify:track:5m7E01gHsMYn0yRIuqALQO May 27 14:40:06 volumio volumio[998]: info: Using cached record of: spotify:track:5m7E01gHsMYn0yRIuqALQO May 27 14:40:06 volumio volumio[998]: info: Adding Item to queue: spotify:track:5wFZ2DZeeUzaXWUsBFIF46 May 27 14:40:06 volumio volumio[998]: info: Using cached record of: spotify:track:5wFZ2DZeeUzaXWUsBFIF46 May 27 14:40:06 volumio volumio[998]: info: Adding Item to queue: spotify:track:0RjLEfhISRNgzKOoQ23mSZ May 27 14:40:06 volumio volumio[998]: info: Using cached record of: spotify:track:0RjLEfhISRNgzKOoQ23mSZ May 27 14:40:06 volumio volumio[998]: info: Adding Item to queue: spotify:track:0vBxoBYyxAFbk85kCA7wY8 May 27 14:40:06 volumio volumio[998]: info: Using cached record of: spotify:track:0vBxoBYyxAFbk85kCA7wY8 May 27 14:40:06 volumio volumio[998]: info: Adding Item to queue: spotify:track:4WuVSEKikU6ER0i5suO6qR May 27 14:40:06 volumio volumio[998]: info: Using cached record of: spotify:track:4WuVSEKikU6ER0i5suO6qR May 27 14:40:06 volumio volumio[998]: info: Adding Item to queue: spotify:track:44Q1YUwzMudaJxmKK7w0rN May 27 14:40:06 volumio volumio[998]: info: Using cached record of: spotify:track:44Q1YUwzMudaJxmKK7w0rN May 27 14:40:06 volumio volumio[998]: info: CoreStateMachine::stop May 27 14:40:06 volumio volumio[998]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 14:40:06 volumio volumio[998]: info: CoreCommandRouter::volumioPushQueue May 27 14:40:06 volumio volumio[998]: info: CorePlayQueue::saveQueue May 27 14:40:06 volumio volumio[998]: info: CoreStateMachine::play index undefined May 27 14:40:06 volumio volumio[998]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 14:40:06 volumio volumio[998]: info: CoreStateMachine::updateTrackBlock May 27 14:40:06 volumio volumio[998]: info: CorePlayQueue::getTrackBlock May 27 14:40:06 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:40:06 volumio volumio[998]: info: CoreStateMachine::startPlaybackTimer May 27 14:40:06 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:40:06 volumio volumio[998]: info: [1748382006746] ControllerSpotify::clearAddPlayTrack May 27 14:40:06 volumio volumio[998]: info: Sending Spotify command with payload to local API: /player/play May 27 14:40:06 volumio go-librespot[1549]: time="2025-05-27T14:40:06-07:00" level=debug msg="resolved context of track" uri="spotify:track:4sWZOj02iWOTHijL4DKEDy" May 27 14:40:06 volumio go-librespot[1549]: time="2025-05-27T14:40:06-07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4sWZOj02iWOTHijL4DKEDy" May 27 14:40:06 volumio go-librespot[1549]: time="2025-05-27T14:40:06-07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4sWZOj02iWOTHijL4DKEDy" May 27 14:40:07 volumio go-librespot[1549]: time="2025-05-27T14:40:07-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 27 14:40:07 volumio go-librespot[1549]: time="2025-05-27T14:40:07-07:00" level=trace msg="emitting websocket event: will_play" May 27 14:40:07 volumio volumio[998]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","play_origin":"go-librespot"}} May 27 14:40:07 volumio go-librespot[1549]: time="2025-05-27T14:40:07-07:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 27 14:40:07 volumio go-librespot[1549]: time="2025-05-27T14:40:07-07:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 27 14:40:07 volumio go-librespot[1549]: time="2025-05-27T14:40:07-07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 27 14:40:07 volumio go-librespot[1549]: time="2025-05-27T14:40:07-07:00" level=debug msg="selected format OGG_VORBIS_160 (119e53b7322f5adf409b421b87f4d1345bfc2c0c)" uri="spotify:track:4sWZOj02iWOTHijL4DKEDy" May 27 14:40:07 volumio go-librespot[1549]: time="2025-05-27T14:40:07-07:00" level=debug msg="requested aes key for file 119e53b7322f5adf409b421b87f4d1345bfc2c0c, gid: 4sWZOj02iWOTHijL4DKEDy" May 27 14:40:07 volumio go-librespot[1549]: time="2025-05-27T14:40:07-07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1127" May 27 14:40:08 volumio go-librespot[1549]: time="2025-05-27T14:40:08-07:00" level=debug msg="fetched first chunk of 12, total size is 6061424 bytes" uri="spotify:track:4sWZOj02iWOTHijL4DKEDy" May 27 14:40:09 volumio go-librespot[1549]: time="2025-05-27T14:40:08-07:00" level=debug msg="created new output device" May 27 14:40:09 volumio go-librespot[1549]: time="2025-05-27T14:40:09-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 27 14:40:09 volumio go-librespot[1549]: time="2025-05-27T14:40:09-07:00" level=info msg="loaded track \"Chuyện buồn ngày xuân\" (paused: false, position: 0ms, duration: 310173ms, prefetched: false)" uri="spotify:track:4sWZOj02iWOTHijL4DKEDy" May 27 14:40:09 volumio go-librespot[1549]: time="2025-05-27T14:40:09-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 27 14:40:09 volumio go-librespot[1549]: time="2025-05-27T14:40:09-07:00" level=trace msg="scheduling prefetch in 280s" May 27 14:40:09 volumio go-librespot[1549]: time="2025-05-27T14:40:09-07:00" level=trace msg="emitting websocket event: metadata" May 27 14:40:09 volumio volumio[998]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","name":"Chuyện buồn ngày xuân","artist_names":["Giao Linh"],"album_name":"Giao Linh - Tâm sự với anh","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02dd0ae6989e96ce41da72741d","position":0,"duration":310173,"release_date":"year:1996 month:4 day:1","track_number":1,"disc_number":1}} May 27 14:40:09 volumio go-librespot[1549]: time="2025-05-27T14:40:09-07:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:4sWZOj02iWOTHijL4DKEDy" May 27 14:40:09 volumio go-librespot[1549]: time="2025-05-27T14:40:09-07:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:4sWZOj02iWOTHijL4DKEDy" May 27 14:40:09 volumio go-librespot[1549]: time="2025-05-27T14:40:09-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 27 14:40:09 volumio go-librespot[1549]: time="2025-05-27T14:40:09-07:00" level=trace msg="emitting websocket event: playing" May 27 14:40:09 volumio volumio[998]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","play_origin":"go-librespot"}} May 27 14:40:09 volumio volumio[998]: SPOTIFY: PUSH STATE SPOTIFY May 27 14:40:09 volumio volumio[998]: SPOTIFY: {"status":"play","service":"spop","title":"Chuyện buồn ngày xuân","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","albumart":"https://i.scdn.co/image/ab67616d00001e02dd0ae6989e96ce41da72741d","uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","trackType":"spotify","seek":0,"duration":310,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 27 14:40:09 volumio volumio[998]: info: CoreCommandRouter::servicePushState May 27 14:40:09 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:40:09 volumio volumio[998]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Chuyện buồn ngày xuân","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","albumart":"https://i.scdn.co/image/ab67616d00001e02dd0ae6989e96ce41da72741d","uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","trackType":"spotify","seek":0,"duration":310,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 27 14:40:09 volumio volumio[998]: verbose: CURRENT POSITION 0 May 27 14:40:09 volumio volumio[998]: info: CoreStateMachine::syncState stateService play May 27 14:40:09 volumio volumio[998]: info: CoreStateMachine::syncState currentStatus stop May 27 14:40:09 volumio go-librespot[1549]: time="2025-05-27T14:40:09-07:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:4sWZOj02iWOTHijL4DKEDy" May 27 14:40:09 volumio volumio[998]: SPOTIFY: PUSH STATE SPOTIFY May 27 14:40:09 volumio volumio[998]: SPOTIFY: {"status":"play","service":"spop","title":"Chuyện buồn ngày xuân","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","albumart":"https://i.scdn.co/image/ab67616d00001e02dd0ae6989e96ce41da72741d","uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","trackType":"spotify","seek":0,"duration":310,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 27 14:40:09 volumio volumio[998]: info: CoreCommandRouter::servicePushState May 27 14:40:09 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:40:09 volumio volumio[998]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Chuyện buồn ngày xuân","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","albumart":"https://i.scdn.co/image/ab67616d00001e02dd0ae6989e96ce41da72741d","uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","trackType":"spotify","seek":0,"duration":310,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 27 14:40:09 volumio volumio[998]: verbose: CURRENT POSITION 0 May 27 14:40:09 volumio volumio[998]: info: CoreStateMachine::syncState stateService play May 27 14:40:09 volumio volumio[998]: info: CoreStateMachine::syncState currentStatus play May 27 14:40:09 volumio volumio[998]: info: Received an update from plugin. extracting info from payload May 27 14:40:09 volumio volumio[998]: info: CoreStateMachine::pushState May 27 14:40:09 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:40:09 volumio volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 14:40:09 volumio volumio[998]: info: CoreCommandRouter::volumioPushState May 27 14:40:09 volumio volumio[998]: info: CoreStateMachine::pushState May 27 14:40:09 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:40:09 volumio volumio[998]: info: CoreCommandRouter::volumioPushState May 27 14:40:09 volumio volumio[998]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 May 27 14:40:09 volumio volumio[998]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 May 27 14:40:11 volumio go-librespot[1549]: time="2025-05-27T14:40:11-07:00" level=trace msg="sent dealer ping" May 27 14:40:11 volumio go-librespot[1549]: time="2025-05-27T14:40:11-07:00" level=trace msg="received dealer pong" May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::executeOnPlugin: mpd , updateDb May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::sendMpdCommand update May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 27 14:40:23 volumio volumio[998]: info: May 27 14:40:23 volumio volumio[998]: ---------------------------- MPD announces state update: update May 27 14:40:23 volumio volumio[998]: info: sendMpdCommand update took 7 milliseconds May 27 14:40:23 volumio volumio[998]: info: ControllerMpd::getState May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 27 14:40:23 volumio volumio[998]: info: May 27 14:40:23 volumio volumio[998]: ---------------------------- MPD announces state update: update May 27 14:40:23 volumio volumio[998]: info: ControllerMpd::getState May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 27 14:40:23 volumio volumio[998]: info: sendMpdCommand status took 7 milliseconds May 27 14:40:23 volumio volumio[998]: info: sendMpdCommand status took 4 milliseconds May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::parseState May 27 14:40:23 volumio volumio[998]: info: Command Router : Notfying DB Updatefalse May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::Close All Modals sent May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::parseState May 27 14:40:23 volumio volumio[998]: info: ControllerMpd::pushState May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::servicePushState May 27 14:40:23 volumio volumio[998]: info: CoreStateMachine::pushState May 27 14:40:23 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::volumioPushState May 27 14:40:23 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:40:23 volumio volumio[998]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd May 27 14:40:23 volumio volumio[998]: info: ------------------------------ 67ms May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 27 14:40:23 volumio volumio[998]: info: May 27 14:40:23 volumio volumio[998]: ---------------------------- MPD announces state update: update May 27 14:40:23 volumio volumio[998]: info: ControllerMpd::getState May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 27 14:40:23 volumio volumio[998]: info: May 27 14:40:23 volumio volumio[998]: ---------------------------- MPD announces state update: update May 27 14:40:23 volumio volumio[998]: info: ControllerMpd::getState May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 27 14:40:23 volumio volumio[998]: info: sendMpdCommand status took 69 milliseconds May 27 14:40:23 volumio volumio[998]: info: sendMpdCommand status took 68 milliseconds May 27 14:40:23 volumio volumio[998]: info: sendMpdCommand status took 7 milliseconds May 27 14:40:23 volumio volumio[998]: info: sendMpdCommand status took 6 milliseconds May 27 14:40:23 volumio volumio[998]: info: sendMpdCommand status took 5 milliseconds May 27 14:40:23 volumio volumio[998]: info: sendMpdCommand status took 3 milliseconds May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::parseState May 27 14:40:23 volumio volumio[998]: info: Command Router : Notfying DB Updatefalse May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::Close All Modals sent May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::parseState May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::parseState May 27 14:40:23 volumio volumio[998]: info: Command Router : Notfying DB Updatefalse May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::Close All Modals sent May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::parseState May 27 14:40:23 volumio volumio[998]: info: Command Router : Notfying DB Updatefalse May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::Close All Modals sent May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::parseState May 27 14:40:23 volumio volumio[998]: info: ControllerMpd::pushState May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::servicePushState May 27 14:40:23 volumio volumio[998]: info: CoreStateMachine::pushState May 27 14:40:23 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::volumioPushState May 27 14:40:23 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:40:23 volumio volumio[998]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd May 27 14:40:23 volumio volumio[998]: info: ControllerMpd::pushState May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::servicePushState May 27 14:40:23 volumio volumio[998]: info: CoreStateMachine::pushState May 27 14:40:23 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::volumioPushState May 27 14:40:23 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:40:23 volumio volumio[998]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd May 27 14:40:23 volumio volumio[998]: info: ControllerMpd::pushState May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::servicePushState May 27 14:40:23 volumio volumio[998]: info: CoreStateMachine::pushState May 27 14:40:23 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::volumioPushState May 27 14:40:23 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:40:23 volumio volumio[998]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd May 27 14:40:23 volumio volumio[998]: info: ------------------------------ 198ms May 27 14:40:23 volumio volumio[998]: info: ------------------------------ 135ms May 27 14:40:23 volumio volumio[998]: info: ------------------------------ 134ms May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 27 14:40:23 volumio volumio[998]: info: May 27 14:40:23 volumio volumio[998]: ---------------------------- MPD announces state update: update May 27 14:40:23 volumio volumio[998]: info: ControllerMpd::getState May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 27 14:40:23 volumio volumio[998]: info: May 27 14:40:23 volumio volumio[998]: ---------------------------- MPD announces state update: update May 27 14:40:23 volumio volumio[998]: info: ControllerMpd::getState May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 27 14:40:23 volumio volumio[998]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 May 27 14:40:23 volumio volumio[998]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 May 27 14:40:23 volumio volumio[998]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 May 27 14:40:23 volumio volumio[998]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 May 27 14:40:23 volumio volumio[998]: info: sendMpdCommand status took 15 milliseconds May 27 14:40:23 volumio volumio[998]: info: sendMpdCommand status took 14 milliseconds May 27 14:40:23 volumio volumio[998]: info: sendMpdCommand status took 14 milliseconds May 27 14:40:23 volumio volumio[998]: info: sendMpdCommand status took 13 milliseconds May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::parseState May 27 14:40:23 volumio volumio[998]: info: Command Router : Notfying DB Updatefalse May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::Close All Modals sent May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::parseState May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::parseState May 27 14:40:23 volumio volumio[998]: info: Command Router : Notfying DB Updatefalse May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::Close All Modals sent May 27 14:40:23 volumio volumio[998]: verbose: ControllerMpd::parseState May 27 14:40:23 volumio volumio[998]: info: ControllerMpd::pushState May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::servicePushState May 27 14:40:23 volumio volumio[998]: info: CoreStateMachine::pushState May 27 14:40:23 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::volumioPushState May 27 14:40:23 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:40:23 volumio volumio[998]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd May 27 14:40:23 volumio volumio[998]: info: ControllerMpd::pushState May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::servicePushState May 27 14:40:23 volumio volumio[998]: info: CoreStateMachine::pushState May 27 14:40:23 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:40:23 volumio volumio[998]: info: CoreCommandRouter::volumioPushState May 27 14:40:23 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:40:23 volumio volumio[998]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd May 27 14:40:23 volumio volumio[998]: info: ------------------------------ 87ms May 27 14:40:23 volumio volumio[998]: info: ------------------------------ 85ms May 27 14:40:23 volumio volumio[998]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 May 27 14:40:23 volumio volumio[998]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 May 27 14:40:29 volumio ntpd[973]: Soliciting pool server 115.165.161.155 May 27 14:40:32 volumio volumio[998]: info: Listing playlists May 27 14:40:34 volumio volumio[998]: info: CoreCommandRouter::executeOnPlugin: spop , getTrack May 27 14:40:35 volumio ntpd[973]: Soliciting pool server 2404:fbc0:0:2046::c May 27 14:40:35 volumio go-librespot[1549]: time="2025-05-27T14:40:35-07:00" level=debug msg="fetched chunk 4/11, size: 524288" uri="spotify:track:4sWZOj02iWOTHijL4DKEDy" May 27 14:40:39 volumio ntpd[973]: Soliciting pool server 103.184.124.254 May 27 14:40:40 volumio volumio[998]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 27 14:40:40 volumio volumio[998]: info: In handleBrowseUri, curUri=spotify:album:1R9y7ylS5egktBausRtuvV May 27 14:40:40 volumio volumio[998]: info: Preload queue cleared May 27 14:40:41 volumio go-librespot[1549]: time="2025-05-27T14:40:41-07:00" level=trace msg="sent dealer ping" May 27 14:40:41 volumio go-librespot[1549]: time="2025-05-27T14:40:41-07:00" level=trace msg="received dealer pong" May 27 14:41:02 volumio go-librespot[1549]: time="2025-05-27T14:41:02-07:00" level=debug msg="fetched chunk 5/11, size: 524288" uri="spotify:track:4sWZOj02iWOTHijL4DKEDy" May 27 14:41:10 volumio kernel: xhci_hcd 0000:00:14.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 5 comp_code 1 May 27 14:41:10 volumio kernel: xhci_hcd 0000:00:14.0: Looking for event-dma 000000010e608ad0 trb-start 000000010e608ae0 trb-end 000000010e608ae0 seg-start 000000010e608000 seg-end 000000010e608ff0 May 27 14:41:11 volumio go-librespot[1549]: time="2025-05-27T14:41:11-07:00" level=trace msg="received accesspoint ping" May 27 14:41:11 volumio go-librespot[1549]: time="2025-05-27T14:41:11-07:00" level=trace msg="received accesspoint pong ack" May 27 14:41:11 volumio go-librespot[1549]: time="2025-05-27T14:41:11-07:00" level=trace msg="sent dealer ping" May 27 14:41:11 volumio go-librespot[1549]: time="2025-05-27T14:41:11-07:00" level=trace msg="received dealer pong" May 27 14:41:15 volumio go-librespot[1549]: time="2025-05-27T14:41:15-07:00" level=debug msg="handling pause player command from 264dcdd848f93069154e30a3e0a4151e0914769c" May 27 14:41:15 volumio go-librespot[1549]: time="2025-05-27T14:41:15-07:00" level=debug msg="pause track at 66611ms" May 27 14:41:15 volumio go-librespot[1549]: time="2025-05-27T14:41:15-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 27 14:41:15 volumio go-librespot[1549]: time="2025-05-27T14:41:15-07:00" level=debug msg="sending successful reply for dealer request" May 27 14:41:15 volumio go-librespot[1549]: time="2025-05-27T14:41:15-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 27 14:41:15 volumio go-librespot[1549]: time="2025-05-27T14:41:15-07:00" level=trace msg="emitting websocket event: paused" May 27 14:41:15 volumio volumio[998]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","play_origin":"go-librespot"}} May 27 14:41:15 volumio volumio[998]: SPOTIFY: PUSH STATE SPOTIFY May 27 14:41:15 volumio volumio[998]: SPOTIFY: {"status":"pause","service":"spop","title":"Chuyện buồn ngày xuân","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","albumart":"https://i.scdn.co/image/ab67616d00001e02dd0ae6989e96ce41da72741d","uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","trackType":"spotify","seek":66000,"duration":310,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 27 14:41:15 volumio volumio[998]: info: CoreCommandRouter::servicePushState May 27 14:41:15 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:41:15 volumio volumio[998]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Chuyện buồn ngày xuân","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","albumart":"https://i.scdn.co/image/ab67616d00001e02dd0ae6989e96ce41da72741d","uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","trackType":"spotify","seek":66000,"duration":310,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 27 14:41:15 volumio volumio[998]: verbose: CURRENT POSITION 0 May 27 14:41:15 volumio volumio[998]: info: CoreStateMachine::syncState stateService pause May 27 14:41:15 volumio volumio[998]: info: CoreStateMachine::syncState currentStatus play May 27 14:41:15 volumio volumio[998]: info: CoreStateMachine::pushState May 27 14:41:15 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:41:15 volumio volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 14:41:15 volumio volumio[998]: info: CoreCommandRouter::volumioPushState May 27 14:41:15 volumio volumio[998]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 May 27 14:41:20 volumio volumio[998]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/data/albumart/web/giao%20linh/2f31cf64-b21c-4157-ab11-99d1f0d7d17e.jpg' May 27 14:41:26 volumio volumio[998]: verbose: New Socket.io Connection to 192.168.1.20 from 192.168.1.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_7_11 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.6.1 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 6 May 27 14:41:26 volumio volumio[998]: info: CoreCommandRouter::volumioGetState May 27 14:41:26 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:41:26 volumio volumio[998]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 27 14:41:26 volumio volumio[998]: info: Listing playlists May 27 14:41:26 volumio volumio[998]: info: CoreCommandRouter::volumioGetVisibleSources May 27 14:41:26 volumio volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 27 14:41:26 volumio volumio[998]: info: CoreCommandRouter::volumioGetQueue May 27 14:41:26 volumio volumio[998]: info: CoreStateMachine::getQueue May 27 14:41:26 volumio volumio[998]: info: CorePlayQueue::getQueue May 27 14:41:28 volumio volumio[998]: info: CoreCommandRouter::volumioPause May 27 14:41:28 volumio volumio[998]: info: CoreStateMachine::pause May 27 14:41:28 volumio volumio[998]: info: CoreStateMachine::stPlaybackTimer May 27 14:41:28 volumio volumio[998]: info: CoreStateMachine::servicePause May 27 14:41:28 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:41:28 volumio volumio[998]: info: CoreCommandRouter::servicePause May 27 14:41:28 volumio volumio[998]: info: Spotify Received pause May 27 14:41:28 volumio volumio[998]: SPOTIFY: SPOTIFY PAUSE May 27 14:41:28 volumio volumio[998]: SPOTIFY: {"status":"play","position":0,"title":"Chuyện buồn ngày xuân","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","albumart":"https://i.scdn.co/image/ab67616d0000b273dd0ae6989e96ce41da72741d","uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","trackType":"spotify","codec":"ogg","seek":66255,"duration":310,"samplerate":"160 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":true,"repeatSingle":false,"consume":false,"volume":70,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} May 27 14:41:28 volumio volumio[998]: info: Sending Spotify command to local API: /player/pause May 27 14:41:28 volumio go-librespot[1549]: time="2025-05-27T14:41:28-07:00" level=debug msg="pause track at 67051ms" May 27 14:41:29 volumio go-librespot[1549]: time="2025-05-27T14:41:29-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 27 14:41:29 volumio go-librespot[1549]: time="2025-05-27T14:41:29-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 27 14:41:29 volumio go-librespot[1549]: time="2025-05-27T14:41:29-07:00" level=trace msg="emitting websocket event: paused" May 27 14:41:29 volumio volumio[998]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","play_origin":"go-librespot"}} May 27 14:41:29 volumio volumio[998]: SPOTIFY: PUSH STATE SPOTIFY May 27 14:41:29 volumio volumio[998]: SPOTIFY: {"status":"pause","service":"spop","title":"Chuyện buồn ngày xuân","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","albumart":"https://i.scdn.co/image/ab67616d00001e02dd0ae6989e96ce41da72741d","uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","trackType":"spotify","seek":66000,"duration":310,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 27 14:41:29 volumio volumio[998]: info: CoreCommandRouter::servicePushState May 27 14:41:29 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:41:29 volumio volumio[998]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Chuyện buồn ngày xuân","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","albumart":"https://i.scdn.co/image/ab67616d00001e02dd0ae6989e96ce41da72741d","uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","trackType":"spotify","seek":66000,"duration":310,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 27 14:41:29 volumio volumio[998]: verbose: CURRENT POSITION 0 May 27 14:41:29 volumio volumio[998]: info: CoreStateMachine::syncState stateService pause May 27 14:41:29 volumio volumio[998]: info: CoreStateMachine::syncState currentStatus pause May 27 14:41:29 volumio volumio[998]: info: CoreStateMachine::pushState May 27 14:41:29 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:41:29 volumio volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 14:41:29 volumio volumio[998]: info: CoreCommandRouter::volumioPushState May 27 14:41:29 volumio volumio[998]: info: CoreStateMachine::stPlaybackTimer May 27 14:41:29 volumio volumio[998]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 May 27 14:41:30 volumio volumio[998]: info: CoreCommandRouter::volumioPlay May 27 14:41:30 volumio volumio[998]: info: CoreStateMachine::play index undefined May 27 14:41:30 volumio volumio[998]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 14:41:30 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:41:30 volumio volumio[998]: info: CoreStateMachine::startPlaybackTimer May 27 14:41:30 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:41:30 volumio volumio[998]: info: Spotify Resume May 27 14:41:30 volumio volumio[998]: info: Sending Spotify command to local API: /player/resume May 27 14:41:30 volumio go-librespot[1549]: time="2025-05-27T14:41:30-07:00" level=debug msg="vorbis: corrupt or missing data in bitstream" uri="spotify:track:4sWZOj02iWOTHijL4DKEDy" May 27 14:41:30 volumio go-librespot[1549]: time="2025-05-27T14:41:30-07:00" level=trace msg="seek to 67051ms (diff: 209ms, samples: 2956949, bytes: 1296840)" uri="spotify:track:4sWZOj02iWOTHijL4DKEDy" May 27 14:41:30 volumio go-librespot[1549]: time="2025-05-27T14:41: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 27 14:41:30 volumio go-librespot[1549]: time="2025-05-27T14:41:30-07:00" level=debug msg="resume track at 66842ms" May 27 14:41:30 volumio go-librespot[1549]: time="2025-05-27T14:41:30-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 27 14:41:30 volumio go-librespot[1549]: time="2025-05-27T14:41:30-07:00" level=trace msg="scheduling prefetch in 213s" May 27 14:41:31 volumio go-librespot[1549]: time="2025-05-27T14:41:31-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 27 14:41:31 volumio go-librespot[1549]: time="2025-05-27T14:41:31-07:00" level=trace msg="emitting websocket event: playing" May 27 14:41:31 volumio volumio[998]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","play_origin":"go-librespot"}} May 27 14:41:31 volumio volumio[998]: SPOTIFY: PUSH STATE SPOTIFY May 27 14:41:31 volumio volumio[998]: SPOTIFY: {"status":"play","service":"spop","title":"Chuyện buồn ngày xuân","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","albumart":"https://i.scdn.co/image/ab67616d00001e02dd0ae6989e96ce41da72741d","uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","trackType":"spotify","seek":66000,"duration":310,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 27 14:41:31 volumio volumio[998]: info: CoreCommandRouter::servicePushState May 27 14:41:31 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:41:31 volumio volumio[998]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Chuyện buồn ngày xuân","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","albumart":"https://i.scdn.co/image/ab67616d00001e02dd0ae6989e96ce41da72741d","uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","trackType":"spotify","seek":66000,"duration":310,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 27 14:41:31 volumio volumio[998]: verbose: CURRENT POSITION 0 May 27 14:41:31 volumio volumio[998]: info: CoreStateMachine::syncState stateService play May 27 14:41:31 volumio volumio[998]: info: CoreStateMachine::syncState currentStatus pause May 27 14:41:31 volumio volumio[998]: info: CoreStateMachine::pushState May 27 14:41:31 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:41:31 volumio volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 14:41:31 volumio volumio[998]: info: CoreCommandRouter::volumioPushState May 27 14:41:31 volumio volumio[998]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 May 27 14:41:31 volumio volumio[998]: SPOTIFY: PUSH STATE SPOTIFY May 27 14:41:31 volumio volumio[998]: SPOTIFY: {"status":"play","service":"spop","title":"Chuyện buồn ngày xuân","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","albumart":"https://i.scdn.co/image/ab67616d00001e02dd0ae6989e96ce41da72741d","uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","trackType":"spotify","seek":66000,"duration":310,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 27 14:41:31 volumio volumio[998]: info: CoreCommandRouter::servicePushState May 27 14:41:31 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:41:31 volumio volumio[998]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Chuyện buồn ngày xuân","artist":"Giao Linh","album":"Giao Linh - Tâm sự với anh","albumart":"https://i.scdn.co/image/ab67616d00001e02dd0ae6989e96ce41da72741d","uri":"spotify:track:4sWZOj02iWOTHijL4DKEDy","trackType":"spotify","seek":66000,"duration":310,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 27 14:41:31 volumio volumio[998]: verbose: CURRENT POSITION 0 May 27 14:41:31 volumio volumio[998]: info: CoreStateMachine::syncState stateService play May 27 14:41:31 volumio volumio[998]: info: CoreStateMachine::syncState currentStatus play May 27 14:41:31 volumio volumio[998]: info: Received an update from plugin. extracting info from payload May 27 14:41:31 volumio volumio[998]: info: CoreStateMachine::pushState May 27 14:41:31 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:41:31 volumio volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 14:41:31 volumio volumio[998]: info: CoreCommandRouter::volumioPushState May 27 14:41:31 volumio volumio[998]: info: CoreStateMachine::pushState May 27 14:41:31 volumio volumio[998]: info: CorePlayQueue::getTrack 0 May 27 14:41:31 volumio volumio[998]: info: CoreCommandRouter::volumioPushState May 27 14:41:31 volumio volumio[998]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 May 27 14:41:31 volumio volumio[998]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 May 27 14:41:35 volumio ntpd[973]: Soliciting pool server 115.165.161.155 May 27 14:41:39 volumio ntpd[973]: Soliciting pool server 2400:6760:0:200::254 May 27 14:41:40 volumio ntpd[973]: Soliciting pool server 103.184.124.254 May 27 14:41:41 volumio go-librespot[1549]: time="2025-05-27T14:41:41-07:00" level=trace msg="sent dealer ping" May 27 14:41:41 volumio go-librespot[1549]: time="2025-05-27T14:41:41-07:00" level=trace msg="received dealer pong" May 27 14:41:43 volumio ntpd[973]: Soliciting pool server 115.165.161.155 May 27 14:41:44 volumio go-librespot[1549]: time="2025-05-27T14:41:44-07:00" level=debug msg="fetched chunk 6/11, size: 524288" uri="spotify:track:4sWZOj02iWOTHijL4DKEDy" May 27 14:41:44 volumio volumio[998]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 27 14:41:44 volumio volumio[998]: Error: connect ETIMEDOUT 151.101.78.79:80 May 27 14:41:44 volumio volumio[998]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) { May 27 14:41:44 volumio volumio[998]: errno: -110, May 27 14:41:44 volumio volumio[998]: code: 'ETIMEDOUT', May 27 14:41:44 volumio volumio[998]: syscall: 'connect', May 27 14:41:44 volumio volumio[998]: address: '151.101.78.79', May 27 14:41:44 volumio volumio[998]: port: 80 May 27 14:41:44 volumio volumio[998]: } May 27 14:41:44 volumio volumio[998]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 27 14:41:44 volumio sudo[9617]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-27 14:40 May 27 14:41:44 volumio sudo[9617]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 May 2025 05:50:12 PM CEST" VOLUMIO_VERSION="3.812" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="39b0f8c200b2dcadf117e189b4b3632d"