Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

failed handling status request error #93

Open
sciensys opened this issue Sep 12, 2024 · 7 comments
Open

failed handling status request error #93

sciensys opened this issue Sep 12, 2024 · 7 comments
Labels
bug Something isn't working

Comments

@sciensys
Copy link

sciensys commented Sep 12, 2024 •
edited
Loading

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"}}
@sciensys
Copy link
Author

sciensys commented Sep 12, 2024 •
edited
Loading

full_log.txt

@sciensys
Copy link
Author

Another clean reinstallation of the system temporarily solved the issue.

@devgianlu devgianlu added the bug Something isn't working label Sep 16, 2024
@devgianlu
Copy link
Owner

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.

@sciensys
Copy link
Author

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.

@aykevl
Copy link
Contributor

aykevl commented 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 #88 for another example of this.

@sciensys
Copy link
Author

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

@devgianlu
Copy link
Owner

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@aykevl @devgianlu @sciensys