starred/go-librespot
1
0
Fork 0
mirror of https://github.com/devgianlu/go-librespot.git synced 2026-04-26 13:25:49 +03:00
Code Issues 22 Projects Releases 5 Packages Wiki Activity

[GH-ISSUE #93] failed handling status request error #66

New issue
Closed
opened 2026-02-28 14:25:05 +03:00 by kerem · 7 comments
kerem commented 2026-02-28 14:25:05 +03:00
Owner
Copy link

Originally created by @sciensys on GitHub (Sep 12, 2024).
Original GitHub issue: https://github.com/devgianlu/go-librespot/issues/93

hello,
during last week plugin regularly stops play and then start freezing control.

any ideas?

Sep 12 12:19:46 main volumio[827]: info: CorePlayQueue::getTrack 0
Sep 12 12:19:46 main volumio[827]: info: CorePlayQueue::getTrack 12
Sep 12 12:19:46 main volumio[827]: info: Prefetching next song
Sep 12 12:19:46 main volumio[827]: info: [1726132786647] ControllerSpotify::prefetch
Sep 12 12:19:46 main volumio[827]: info: Sending Spotify command with payload to local API: /player/add_to_queue
Sep 12 12:19:51 main volumio[827]: info: CoreStateMachine::startPlaybackTimer
Sep 12 12:19:51 main volumio[827]: info: CorePlayQueue::getTrack 12
Sep 12 12:19:51 main volumio[827]: info: CoreStateMachine::pushState
Sep 12 12:19:51 main volumio[827]: info: CorePlayQueue::getTrack 12
Sep 12 12:19:51 main volumio[827]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Sep 12 12:19:51 main volumio[827]: info: CoreCommandRouter::volumioPushState
Sep 12 12:19:51 main volumio[827]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Sep 12 12:21:12 main go-librespot[2010]: time="2024-09-12T12:21:12+03:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:06DSI8L6IT8SizCw3JLckz: failed initializing chunked reader: failed reading first chunk: read tcp 192.168.70.10:53542->86.57.191.82:443: read: connection reset by peer"
Sep 12 12:21:12 main volumio[827]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error
Sep 12 12:21:13 main go-librespot[2010]: time="2024-09-12T12:21:13+03:00" level=debug msg="resolved context of track" uri="spotify:track:06DSI8L6IT8SizCw3JLckz"
Sep 12 12:21:13 main go-librespot[2010]: time="2024-09-12T12:21:13+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:06DSI8L6IT8SizCw3JLckz"
Sep 12 12:21:13 main go-librespot[2010]: time="2024-09-12T12:21:13+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:06DSI8L6IT8SizCw3JLckz"
Sep 12 12:21:13 main go-librespot[2010]: time="2024-09-12T12:21:13+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Sep 12 12:21:13 main go-librespot[2010]: time="2024-09-12T12:21:13+03:00" level=trace msg="emitting websocket event: will_play"
Sep 12 12:21:13 main volumio[827]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:06DSI8L6IT8SizCw3JLckz","play_origin":"go-librespot"}}
Sep 12 12:21:13 main volumio[827]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:06DSI8L6IT8SizCw3JLckz","play_origin":"go-librespot"}}
Sep 12 12:21:13 main go-librespot[2010]: time="2024-09-12T12:21:13+03:00" level=debug msg="selected format OGG_VORBIS_320 (b0371a74409090f0ada5d54d5a083c5d8c95a50a)" uri="spotify:track:06DSI8L6IT8SizCw3JLckz"
Sep 12 12:21:13 main go-librespot[2010]: time="2024-09-12T12:21:13+03:00" level=debug msg="requested aes key for file b0371a74409090f0ada5d54d5a083c5d8c95a50a, gid: 06DSI8L6IT8SizCw3JLckz"
Sep 12 12:21:36 main volumio[827]: verbose: New Socket.io Connection to 192.168.70.10 from 192.168.50.50 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 12_5_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/12.1.2 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 6
Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::volumioGetVisibleSources
Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::volumioGetState
Sep 12 12:21:36 main volumio[827]: info: CorePlayQueue::getTrack 12
Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback
Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
Sep 12 12:21:36 main volumio[827]: info: Received Get System Info
Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Sep 12 12:21:36 main volumio[827]: info: Discovery: Getting this device information
Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::volumioGetState
Sep 12 12:21:36 main volumio[827]: info: CorePlayQueue::getTrack 12
Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::volumioGetState
Sep 12 12:21:36 main volumio[827]: info: CorePlayQueue::getTrack 12
Sep 12 12:21:36 main volumio[827]: info: Listing playlists
Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache
Sep 12 12:21:38 main volumio[827]: info: CoreCommandRouter::volumioPlay
Sep 12 12:21:38 main volumio[827]: info: CoreStateMachine::play index undefined
Sep 12 12:21:38 main volumio[827]: info: CoreStateMachine::setConsumeUpdateService undefined
Sep 12 12:21:38 main volumio[827]: info: CorePlayQueue::getTrack 12
Sep 12 12:21:38 main volumio[827]: info: CoreStateMachine::startPlaybackTimer
Sep 12 12:21:38 main volumio[827]: info: CorePlayQueue::getTrack 12
Sep 12 12:21:38 main volumio[827]: info: [1726132898838] ControllerSpotify::clearAddPlayTrack
Sep 12 12:21:38 main volumio[827]: info: Sending Spotify command with payload to local API: /player/play
Sep 12 12:21:39 main volumio[827]: info: CoreCommandRouter::volumioPlay
Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::play index undefined
Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::setConsumeUpdateService undefined
Sep 12 12:21:39 main volumio[827]: info: CorePlayQueue::getTrack 12
Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::startPlaybackTimer
Sep 12 12:21:39 main volumio[827]: info: CorePlayQueue::getTrack 12
Sep 12 12:21:39 main volumio[827]: info: [1726132899382] ControllerSpotify::clearAddPlayTrack
Sep 12 12:21:39 main volumio[827]: info: Sending Spotify command with payload to local API: /player/play
Sep 12 12:21:39 main volumio[827]: info: CoreCommandRouter::volumioNext
Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::next
Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::stop
Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::setConsumeUpdateService undefined
Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::play index undefined
Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::setConsumeUpdateService undefined
Sep 12 12:21:39 main volumio[827]: info: CorePlayQueue::getTrack 7
Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::startPlaybackTimer
Sep 12 12:21:39 main volumio[827]: info: CorePlayQueue::getTrack 7
Sep 12 12:21:39 main volumio[827]: info: [1726132899694] ControllerSpotify::clearAddPlayTrack
Sep 12 12:21:39 main volumio[827]: info: Sending Spotify command with payload to local API: /player/play
Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::updateTrackBlock
Sep 12 12:21:39 main volumio[827]: info: CorePlayQueue::getTrackBlock
Sep 12 12:21:40 main volumio[827]: info: CoreCommandRouter::volumioNext
Sep 12 12:21:40 main volumio[827]: info: CoreStateMachine::next
Sep 12 12:21:40 main volumio[827]: info: CoreStateMachine::stop
Sep 12 12:21:40 main volumio[827]: info: CoreStateMachine::setConsumeUpdateService undefined
Sep 12 12:21:40 main volumio[827]: info: CoreStateMachine::play index undefined
Sep 12 12:21:40 main volumio[827]: info: CoreStateMachine::setConsumeUpdateService undefined
Sep 12 12:21:40 main volumio[827]: info: CorePlayQueue::getTrack 17
Sep 12 12:21:40 main volumio[827]: info: CoreStateMachine::startPlaybackTimer
Sep 12 12:21:40 main volumio[827]: info: CorePlayQueue::getTrack 17
Sep 12 12:21:40 main volumio[827]: info: [1726132900176] ControllerSpotify::clearAddPlayTrack
Sep 12 12:21:40 main volumio[827]: info: Sending Spotify command with payload to local API: /player/play
Sep 12 12:21:40 main volumio[827]: info: CoreStateMachine::updateTrackBlock
Sep 12 12:21:40 main volumio[827]: info: CorePlayQueue::getTrackBlock
Sep 12 12:21:41 main volumio[827]: info: CoreCommandRouter::volumioPlay
Sep 12 12:21:41 main volumio[827]: info: CoreStateMachine::play index undefined
Sep 12 12:21:41 main volumio[827]: info: CoreStateMachine::setConsumeUpdateService undefined
Sep 12 12:21:41 main volumio[827]: info: CorePlayQueue::getTrack 17
Sep 12 12:21:41 main volumio[827]: info: CoreStateMachine::startPlaybackTimer
Sep 12 12:21:41 main volumio[827]: info: CorePlayQueue::getTrack 17
Sep 12 12:21:41 main volumio[827]: info: [1726132901123] ControllerSpotify::clearAddPlayTrack
Sep 12 12:21:41 main volumio[827]: info: Sending Spotify command with payload to local API: /player/play
Sep 12 12:21:41 main volumio[827]: info: CoreCommandRouter::volumioPlay
Sep 12 12:21:41 main volumio[827]: info: CoreStateMachine::play index undefined
Sep 12 12:21:41 main volumio[827]: info: CoreStateMachine::setConsumeUpdateService undefined
Sep 12 12:21:41 main volumio[827]: info: CorePlayQueue::getTrack 17
Sep 12 12:21:41 main volumio[827]: info: CoreStateMachine::startPlaybackTimer
Sep 12 12:21:41 main volumio[827]: info: CorePlayQueue::getTrack 17
Sep 12 12:21:41 main volumio[827]: info: [1726132901366] ControllerSpotify::clearAddPlayTrack
Sep 12 12:21:41 main volumio[827]: info: Sending Spotify command with payload to local API: /player/play
Sep 12 12:21:56 main go-librespot[2010]: time="2024-09-12T12:21:56+03:00" level=debug msg="fetched first chunk of 23, total size is 11642640 bytes" uri="spotify:track:06DSI8L6IT8SizCw3JLckz"
Sep 12 12:21:56 main go-librespot[2010]: time="2024-09-12T12:21:56+03:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:06DSI8L6IT8SizCw3JLckz"
Sep 12 12:21:56 main kernel: pcm512x 1-004d: No SCLK, using BCLK: -2
Sep 12 12:21:56 main go-librespot[2010]: time="2024-09-12T12:21:56+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames"
Sep 12 12:21:56 main go-librespot[2010]: time="2024-09-12T12:21:56+03:00" level=info msg="loaded track "Cantaloop (Flip Fantasia)" (paused: false, position: 0ms, duration: 279360ms, prefetched: false)" uri="spotify:track:06DSI8L6IT8SizCw3JLckz"
Sep 12 12:21:57 main go-librespot[2010]: time="2024-09-12T12:21:57+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Sep 12 12:21:57 main go-librespot[2010]: time="2024-09-12T12:21:57+03:00" level=trace msg="scheduling prefetch in 249s"
Sep 12 12:21:57 main go-librespot[2010]: time="2024-09-12T12:21:57+03:00" level=trace msg="emitting websocket event: metadata"
Sep 12 12:21:57 main volumio[827]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:06DSI8L6IT8SizCw3JLckz","name":"Cantaloop (Flip Fantasia)","artist_names":["Us3","Rahsaan","Gerard Presencer"],"album_name":"Hand On The Torch","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0243652f722c146ccaf19e2019","position":0,"duration":279360,"release_date":"year:1993 month:1 day:1","track_number":1,"disc_number":1}}
Sep 12 12:21:57 main volumio[827]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:06DSI8L6IT8SizCw3JLckz","name":"Cantaloop (Flip Fantasia)","artist_names":["Us3","Rahsaan","Gerard Presencer"],"album_name":"Hand On The Torch","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0243652f722c146ccaf19e2019","position":0,"duration":279360,"release_date":"year:1993 month:1 day:1","track_number":1,"disc_number":1}}
Sep 12 12:21:57 main go-librespot[2010]: time="2024-09-12T12:21:57+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Sep 12 12:21:57 main go-librespot[2010]: time="2024-09-12T12:21:57+03:00" level=trace msg="emitting websocket event: playing"
Sep 12 12:21:57 main volumio[827]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:06DSI8L6IT8SizCw3JLckz","play_origin":"go-librespot"}}

Originally created by @sciensys on GitHub (Sep 12, 2024). Original GitHub issue: https://github.com/devgianlu/go-librespot/issues/93 hello, during last week plugin regularly stops play and then start freezing control. any ideas? > Sep 12 12:19:46 main volumio[827]: info: CorePlayQueue::getTrack 0 > Sep 12 12:19:46 main volumio[827]: info: CorePlayQueue::getTrack 12 > Sep 12 12:19:46 main volumio[827]: info: Prefetching next song > Sep 12 12:19:46 main volumio[827]: info: [1726132786647] ControllerSpotify::prefetch > Sep 12 12:19:46 main volumio[827]: info: Sending Spotify command with payload to local API: /player/add_to_queue > Sep 12 12:19:51 main volumio[827]: info: CoreStateMachine::startPlaybackTimer > Sep 12 12:19:51 main volumio[827]: info: CorePlayQueue::getTrack 12 > Sep 12 12:19:51 main volumio[827]: info: CoreStateMachine::pushState > Sep 12 12:19:51 main volumio[827]: info: CorePlayQueue::getTrack 12 > Sep 12 12:19:51 main volumio[827]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo > Sep 12 12:19:51 main volumio[827]: info: CoreCommandRouter::volumioPushState > Sep 12 12:19:51 main volumio[827]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60 > Sep 12 12:21:12 main go-librespot[2010]: time="2024-09-12T12:21:12+03:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:06DSI8L6IT8SizCw3JLckz: failed initializing chunked reader: failed reading first chunk: read tcp 192.168.70.10:53542->86.57.191.82:443: read: connection reset by peer" > Sep 12 12:21:12 main volumio[827]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error > Sep 12 12:21:13 main go-librespot[2010]: time="2024-09-12T12:21:13+03:00" level=debug msg="resolved context of track" uri="spotify:track:06DSI8L6IT8SizCw3JLckz" > Sep 12 12:21:13 main go-librespot[2010]: time="2024-09-12T12:21:13+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:06DSI8L6IT8SizCw3JLckz" > Sep 12 12:21:13 main go-librespot[2010]: time="2024-09-12T12:21:13+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:06DSI8L6IT8SizCw3JLckz" > Sep 12 12:21:13 main go-librespot[2010]: time="2024-09-12T12:21:13+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" > Sep 12 12:21:13 main go-librespot[2010]: time="2024-09-12T12:21:13+03:00" level=trace msg="emitting websocket event: will_play" > Sep 12 12:21:13 main volumio[827]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:06DSI8L6IT8SizCw3JLckz","play_origin":"go-librespot"}} > Sep 12 12:21:13 main volumio[827]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:06DSI8L6IT8SizCw3JLckz","play_origin":"go-librespot"}} > Sep 12 12:21:13 main go-librespot[2010]: time="2024-09-12T12:21:13+03:00" level=debug msg="selected format OGG_VORBIS_320 (b0371a74409090f0ada5d54d5a083c5d8c95a50a)" uri="spotify:track:06DSI8L6IT8SizCw3JLckz" > Sep 12 12:21:13 main go-librespot[2010]: time="2024-09-12T12:21:13+03:00" level=debug msg="requested aes key for file b0371a74409090f0ada5d54d5a083c5d8c95a50a, gid: 06DSI8L6IT8SizCw3JLckz" > Sep 12 12:21:36 main volumio[827]: verbose: New Socket.io Connection to 192.168.70.10 from 192.168.50.50 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 12_5_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/12.1.2 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 6 > Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled > Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::volumioGetVisibleSources > Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources > Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::volumioGetState > Sep 12 12:21:36 main volumio[827]: info: CorePlayQueue::getTrack 12 > Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback > Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom > Sep 12 12:21:36 main volumio[827]: info: Received Get System Info > Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo > Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice > Sep 12 12:21:36 main volumio[827]: info: Discovery: Getting this device information > Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::volumioGetState > Sep 12 12:21:36 main volumio[827]: info: CorePlayQueue::getTrack 12 > Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses > Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::volumioGetState > Sep 12 12:21:36 main volumio[827]: info: CorePlayQueue::getTrack 12 > Sep 12 12:21:36 main volumio[827]: info: Listing playlists > Sep 12 12:21:36 main volumio[827]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache > Sep 12 12:21:38 main volumio[827]: info: CoreCommandRouter::volumioPlay > Sep 12 12:21:38 main volumio[827]: info: CoreStateMachine::play index undefined > Sep 12 12:21:38 main volumio[827]: info: CoreStateMachine::setConsumeUpdateService undefined > Sep 12 12:21:38 main volumio[827]: info: CorePlayQueue::getTrack 12 > Sep 12 12:21:38 main volumio[827]: info: CoreStateMachine::startPlaybackTimer > Sep 12 12:21:38 main volumio[827]: info: CorePlayQueue::getTrack 12 > Sep 12 12:21:38 main volumio[827]: info: [1726132898838] ControllerSpotify::clearAddPlayTrack > Sep 12 12:21:38 main volumio[827]: info: Sending Spotify command with payload to local API: /player/play > Sep 12 12:21:39 main volumio[827]: info: CoreCommandRouter::volumioPlay > Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::play index undefined > Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::setConsumeUpdateService undefined > Sep 12 12:21:39 main volumio[827]: info: CorePlayQueue::getTrack 12 > Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::startPlaybackTimer > Sep 12 12:21:39 main volumio[827]: info: CorePlayQueue::getTrack 12 > Sep 12 12:21:39 main volumio[827]: info: [1726132899382] ControllerSpotify::clearAddPlayTrack > Sep 12 12:21:39 main volumio[827]: info: Sending Spotify command with payload to local API: /player/play > Sep 12 12:21:39 main volumio[827]: info: CoreCommandRouter::volumioNext > Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::next > Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::stop > Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::setConsumeUpdateService undefined > Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::play index undefined > Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::setConsumeUpdateService undefined > Sep 12 12:21:39 main volumio[827]: info: CorePlayQueue::getTrack 7 > Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::startPlaybackTimer > Sep 12 12:21:39 main volumio[827]: info: CorePlayQueue::getTrack 7 > Sep 12 12:21:39 main volumio[827]: info: [1726132899694] ControllerSpotify::clearAddPlayTrack > Sep 12 12:21:39 main volumio[827]: info: Sending Spotify command with payload to local API: /player/play > Sep 12 12:21:39 main volumio[827]: info: CoreStateMachine::updateTrackBlock > Sep 12 12:21:39 main volumio[827]: info: CorePlayQueue::getTrackBlock > Sep 12 12:21:40 main volumio[827]: info: CoreCommandRouter::volumioNext > Sep 12 12:21:40 main volumio[827]: info: CoreStateMachine::next > Sep 12 12:21:40 main volumio[827]: info: CoreStateMachine::stop > Sep 12 12:21:40 main volumio[827]: info: CoreStateMachine::setConsumeUpdateService undefined > Sep 12 12:21:40 main volumio[827]: info: CoreStateMachine::play index undefined > Sep 12 12:21:40 main volumio[827]: info: CoreStateMachine::setConsumeUpdateService undefined > Sep 12 12:21:40 main volumio[827]: info: CorePlayQueue::getTrack 17 > Sep 12 12:21:40 main volumio[827]: info: CoreStateMachine::startPlaybackTimer > Sep 12 12:21:40 main volumio[827]: info: CorePlayQueue::getTrack 17 > Sep 12 12:21:40 main volumio[827]: info: [1726132900176] ControllerSpotify::clearAddPlayTrack > Sep 12 12:21:40 main volumio[827]: info: Sending Spotify command with payload to local API: /player/play > Sep 12 12:21:40 main volumio[827]: info: CoreStateMachine::updateTrackBlock > Sep 12 12:21:40 main volumio[827]: info: CorePlayQueue::getTrackBlock > Sep 12 12:21:41 main volumio[827]: info: CoreCommandRouter::volumioPlay > Sep 12 12:21:41 main volumio[827]: info: CoreStateMachine::play index undefined > Sep 12 12:21:41 main volumio[827]: info: CoreStateMachine::setConsumeUpdateService undefined > Sep 12 12:21:41 main volumio[827]: info: CorePlayQueue::getTrack 17 > Sep 12 12:21:41 main volumio[827]: info: CoreStateMachine::startPlaybackTimer > Sep 12 12:21:41 main volumio[827]: info: CorePlayQueue::getTrack 17 > Sep 12 12:21:41 main volumio[827]: info: [1726132901123] ControllerSpotify::clearAddPlayTrack > Sep 12 12:21:41 main volumio[827]: info: Sending Spotify command with payload to local API: /player/play > Sep 12 12:21:41 main volumio[827]: info: CoreCommandRouter::volumioPlay > Sep 12 12:21:41 main volumio[827]: info: CoreStateMachine::play index undefined > Sep 12 12:21:41 main volumio[827]: info: CoreStateMachine::setConsumeUpdateService undefined > Sep 12 12:21:41 main volumio[827]: info: CorePlayQueue::getTrack 17 > Sep 12 12:21:41 main volumio[827]: info: CoreStateMachine::startPlaybackTimer > Sep 12 12:21:41 main volumio[827]: info: CorePlayQueue::getTrack 17 > Sep 12 12:21:41 main volumio[827]: info: [1726132901366] ControllerSpotify::clearAddPlayTrack > Sep 12 12:21:41 main volumio[827]: info: Sending Spotify command with payload to local API: /player/play > Sep 12 12:21:56 main go-librespot[2010]: time="2024-09-12T12:21:56+03:00" level=debug msg="fetched first chunk of 23, total size is 11642640 bytes" uri="spotify:track:06DSI8L6IT8SizCw3JLckz" > Sep 12 12:21:56 main go-librespot[2010]: time="2024-09-12T12:21:56+03:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:06DSI8L6IT8SizCw3JLckz" > Sep 12 12:21:56 main kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 > Sep 12 12:21:56 main go-librespot[2010]: time="2024-09-12T12:21:56+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" > Sep 12 12:21:56 main go-librespot[2010]: time="2024-09-12T12:21:56+03:00" level=info msg="loaded track \"Cantaloop (Flip Fantasia)\" (paused: false, position: 0ms, duration: 279360ms, prefetched: false)" uri="spotify:track:06DSI8L6IT8SizCw3JLckz" > Sep 12 12:21:57 main go-librespot[2010]: time="2024-09-12T12:21:57+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" > Sep 12 12:21:57 main go-librespot[2010]: time="2024-09-12T12:21:57+03:00" level=trace msg="scheduling prefetch in 249s" > Sep 12 12:21:57 main go-librespot[2010]: time="2024-09-12T12:21:57+03:00" level=trace msg="emitting websocket event: metadata" > Sep 12 12:21:57 main volumio[827]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:06DSI8L6IT8SizCw3JLckz","name":"Cantaloop (Flip Fantasia)","artist_names":["Us3","Rahsaan","Gerard Presencer"],"album_name":"Hand On The Torch","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0243652f722c146ccaf19e2019","position":0,"duration":279360,"release_date":"year:1993 month:1 day:1","track_number":1,"disc_number":1}} > Sep 12 12:21:57 main volumio[827]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:06DSI8L6IT8SizCw3JLckz","name":"Cantaloop (Flip Fantasia)","artist_names":["Us3","Rahsaan","Gerard Presencer"],"album_name":"Hand On The Torch","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0243652f722c146ccaf19e2019","position":0,"duration":279360,"release_date":"year:1993 month:1 day:1","track_number":1,"disc_number":1}} > Sep 12 12:21:57 main go-librespot[2010]: time="2024-09-12T12:21:57+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" > Sep 12 12:21:57 main go-librespot[2010]: time="2024-09-12T12:21:57+03:00" level=trace msg="emitting websocket event: playing" > Sep 12 12:21:57 main volumio[827]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:06DSI8L6IT8SizCw3JLckz","play_origin":"go-librespot"}}
kerem 2026-02-28 14:25:05 +03:00
  • closed this issue
  • added the
    bug
         label
kerem commented 2026-02-28 14:25:05 +03:00
Author
Owner
Copy link

@sciensys commented on GitHub (Sep 12, 2024):

full_log.txt

<!-- gh-comment-id:2345787154 --> @sciensys commented on GitHub (Sep 12, 2024): [full_log.txt](https://github.com/user-attachments/files/16977098/full_log.txt)
kerem commented 2026-02-28 14:25:05 +03:00
Author
Owner
Copy link

@sciensys commented on GitHub (Sep 12, 2024):

Another clean reinstallation of the system temporarily solved the issue.

<!-- gh-comment-id:2346458129 --> @sciensys commented on GitHub (Sep 12, 2024): Another clean reinstallation of the system temporarily solved the issue.
kerem commented 2026-02-28 14:25:06 +03:00
Author
Owner
Copy link

@devgianlu commented on GitHub (Sep 16, 2024):

Seems like the heart of the problem is always the network:

failed loading context: failed loading current track (load context): failed creating stream for spotify:track:06DSI8L6IT8SizCw3JLckz: failed initializing chunked reader: failed reading first chunk: read tcp 192.168.70.10:53542->86.57.191.82:443: read: connection reset by peer

Better network failure handling is required all over the place. Anyway, I wouldn't expect a full reinstall to be required, just restarting the device should be enough.

<!-- gh-comment-id:2352345288 --> @devgianlu commented on GitHub (Sep 16, 2024): Seems like the heart of the problem is always the network: ``` failed loading context: failed loading current track (load context): failed creating stream for spotify:track:06DSI8L6IT8SizCw3JLckz: failed initializing chunked reader: failed reading first chunk: read tcp 192.168.70.10:53542->86.57.191.82:443: read: connection reset by peer ``` Better network failure handling is required all over the place. Anyway, I wouldn't expect a full reinstall to be required, just restarting the device should be enough.
kerem commented 2026-02-28 14:25:06 +03:00
Author
Owner
Copy link

@sciensys commented on GitHub (Sep 16, 2024):

Thank you for your attention.

But I'm not quite sure that the problem is in the network, because at that moment I tried to turn on the radio - and it turned on quickly, played sound, and there was a quick, responsive control.

But, using the plugin to listen to Spotify, the control was not responsive, the track began to play with a delay of 5-10 seconds, and after 5 seconds it died down.
At the same time, the playback indicator was fine, but there was no sound.
Rebooting did not help, unlogging and then logging in also did not give a result.
At some point, after unlogging from the plugin, it was no longer possible to log in.
Therefore, there was no choice, only reinstallation, and oddly enough, reinstallation helped, the Spotify plugin immediately started working, quick control, no lags.

I have 3 instances, the first two were installed at the beginning of the previous week, the 3rd at the end of the next week (the last one was fresh, installed 2 weeks ago)

After reinstalling the systems, all 3 instances are still working. I continue to monitor them.

Thank you.

<!-- gh-comment-id:2352386504 --> @sciensys commented on GitHub (Sep 16, 2024): Thank you for your attention. But I'm not quite sure that the problem is in the network, because at that moment I tried to turn on the radio - and it turned on quickly, played sound, and there was a quick, responsive control. But, using the plugin to listen to Spotify, the control was not responsive, the track began to play with a delay of 5-10 seconds, and after 5 seconds it died down. At the same time, the playback indicator was fine, but there was no sound. Rebooting did not help, unlogging and then logging in also did not give a result. At some point, after unlogging from the plugin, it was no longer possible to log in. Therefore, there was no choice, only reinstallation, and oddly enough, reinstallation helped, the Spotify plugin immediately started working, quick control, no lags. I have 3 instances, the first two were installed at the beginning of the previous week, the 3rd at the end of the next week (the last one was fresh, installed 2 weeks ago) After reinstalling the systems, all 3 instances are still working. I continue to monitor them. Thank you.
kerem commented 2026-02-28 14:25:06 +03:00
Author
Owner
Copy link

@aykevl commented on GitHub (Sep 19, 2024):

I also get "connection reset by peer" occasionally. I think it's a problem on Spotify's end, which we will have to work around with more graceful error handling. See https://github.com/devgianlu/go-librespot/issues/88 for another example of this.

<!-- gh-comment-id:2361559160 --> @aykevl commented on GitHub (Sep 19, 2024): I also get "connection reset by peer" occasionally. I think it's a problem on Spotify's end, which we will have to work around with more graceful error handling. See https://github.com/devgianlu/go-librespot/issues/88 for another example of this.
kerem commented 2026-02-28 14:25:06 +03:00
Author
Owner
Copy link

@sciensys commented on GitHub (Oct 12, 2024):

I catched the plugin stop:

time=“2024-10-12T20:12:04+03:00” level=debug msg=“handling pause player command from f31797b295a4877779106bc88a9f72e4cb409336”

Oct 12 20:12:04 living volumio[851]: SPOTIFY: received: {“type”:“paused”,“data”:{“uri”:“spotify:track:6e0LjNPkRqxIAlmmdjWSV8”,“play_origin”:“go-librespot”}}

https://community.volumio.com/t/volumio-3-742-spotify-plugin-4-10-bugs/68418/34?u=sciensys

<!-- gh-comment-id:2408634240 --> @sciensys commented on GitHub (Oct 12, 2024): I catched the plugin stop: > time=“2024-10-12T20:12:04+03:00” level=debug msg=“handling pause player command from f31797b295a4877779106bc88a9f72e4cb409336” > Oct 12 20:12:04 living volumio[851]: SPOTIFY: received: {“type”:“paused”,“data”:{“uri”:“spotify:track:6e0LjNPkRqxIAlmmdjWSV8”,“play_origin”:“go-librespot”}} https://community.volumio.com/t/volumio-3-742-spotify-plugin-4-10-bugs/68418/34?u=sciensys
kerem commented 2026-02-28 14:25:06 +03:00
Author
Owner
Copy link

@devgianlu commented on GitHub (Oct 12, 2024):

@sciensys I have looked at the thread and it does not look like it is an issue with go-librespot.

<!-- gh-comment-id:2408638357 --> @devgianlu commented on GitHub (Oct 12, 2024): @sciensys I have looked at the thread and it does not look like it is an issue with go-librespot.
Sign in to join this conversation.
No Branch/Tag specified
Branches Tags
master
zeroconf-avahi
windows
v0.7.1
v0.7.0
v0.6.2
v0.6.1
v0.6.0
v0.5.3
v0.5.2
v0.5.1
v0.5.0
v0.4.0
v0.3.3
v0.3.2
v0.3.1
v0.3.0
v0.2.0
v0.1.3
v0.1.2
v0.1.1
v0.1.0
v0.0.17.1
v0.0.17
v0.0.16
v0.0.15
v0.0.14
v0.0.13
v0.0.12
v0.0.11
v0.0.10
v0.0.9
v0.0.8
v0.0.7
v0.0.6
v0.0.5
v0.0.4
v0.0.3
v0.0.2
v0.0.1
Labels
Clear labels   
bug

   
enhancement

   
pull-request

Mirrored from GitHub Pull Request

  
spotify-side
No labels
bug
enhancement
pull-request
spotify-side
Milestone
Clear milestone
No items
No milestone
Projects
Clear projects
No items
No project
Assignees
Clear assignees
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference
starred/go-librespot#66
No description provided.