search

washed / drempelbox

0 stars 0 forks source link

librespot channel closed error #19

Open tmh-alex opened 8 months ago

tmh-alex commented 8 months ago

Got this spurious error:

Nov 10 23:40:41 toniblaster drempelbox[1365]: 2023-11-10T22:40:41.859773Z  INFO drempelbox::player: playing spotify from url log_url="https://open.spotify.com/track/4abJbqX8C8CQTXHZxEbJZz?si=f04b62b8e85c4bf1"
Nov 10 23:40:41 toniblaster drempelbox[1365]: Playing...
Nov 10 23:40:41 toniblaster drempelbox[1365]: 2023-11-10T22:40:41.859864Z ERROR librespot_playback::player: Player Commands Error: channel closed
Nov 10 23:40:41 toniblaster drempelbox[1365]: 2023-11-10T22:40:41.864665Z DEBUG hyper::proto::h1::conn: read eof
Nov 10 23:40:47 toniblaster drempelbox[1365]: 2023-11-10T22:40:47.289095Z DEBUG hyper::proto::h1::io: parsed 3 headers
Nov 10 23:40:47 toniblaster drempelbox[1365]: 2023-11-10T22:40:47.289181Z DEBUG hyper::proto::h1::conn: incoming body is empty
Nov 10 23:40:47 toniblaster drempelbox[1365]: 2023-11-10T22:40:47.289273Z  INFO drempelbox::server: Got stop request
Nov 10 23:40:47 toniblaster drempelbox[1365]: 2023-11-10T22:40:47.289313Z  INFO drempelbox::server: submitted stop request
Nov 10 23:40:47 toniblaster drempelbox[1365]: 2023-11-10T22:40:47.289455Z DEBUG hyper::proto::h1::io: flushed 75 bytes
Nov 10 23:40:47 toniblaster drempelbox[1365]: 2023-11-10T22:40:47.289497Z  INFO drempelbox::player: received stop request
Nov 10 23:40:47 toniblaster drempelbox[1365]: 2023-11-10T22:40:47.289542Z  INFO drempelbox::spotify_player: stopping spotify
Nov 10 23:40:47 toniblaster drempelbox[1365]: 2023-11-10T22:40:47.289586Z ERROR librespot_playback::player: Player Commands Error: channel closed
Nov 10 23:40:47 toniblaster drempelbox[1365]: 2023-11-10T22:40:47.297705Z DEBUG hyper::proto::h1::conn: read eof

Couldn't repeat it. The steps that came before this error as far as I can remember:

  1. make track
  2. make stop
  3. A few more times 1 and 2
  4. make volume_up a couple of times while player was stopped
washed commented 8 months ago

Looks like the entire player task died. We will need some sort of watchdog thingy for all of those long running tasks anyhow. I'll think about it. Same for the file player to make sure the sink is still running, the web server is still running etc...

I think the hyper logs are unrelated.

washed commented 8 months ago

Ah, do you have logs before the ones you posted? Ideally from the start of the app until you saw the failure? Even the first play request in the logs you posted seems to have failed.

tmh-alex commented 8 months ago

faulty_boot_session.txt I'm starting to like journalctl. It's even possible to get the logs for a particular boot session. Here're the complete logs for the drempelbox process, tell me if you need all the logs (including kernel messages perhaps?).

washed commented 8 months ago

Awesome, thanks! Looks to me like the spotify player crashed somewhere inside librespot and took the bigger player thread down with it:

Nov 10 23:39:57 toniblaster drempelbox[1365]: 2023-11-10T22:39:57.022170Z  INFO drempelbox::server: Got URL request url="https://open.spotify.com/track/4abJbqX8C8CQTXHZxEbJZz?si=f04b62b8e85c4bf1"
Nov 10 23:39:57 toniblaster drempelbox[1365]: 2023-11-10T22:39:57.022264Z  INFO drempelbox::server: submitted URL request
Nov 10 23:39:57 toniblaster drempelbox[1365]: 2023-11-10T22:39:57.022463Z  INFO drempelbox::player: received URL player request log_url="https://open.spotify.com/track/4abJbqX8C8CQTXHZxEbJZz?si=f04b62b8e85c4bf1"
Nov 10 23:39:57 toniblaster drempelbox[1365]: 2023-11-10T22:39:57.022507Z  INFO drempelbox::player: playing spotify from url log_url="https://open.spotify.com/track/4abJbqX8C8CQTXHZxEbJZz?si=f04b62b8e85c4bf1"
Nov 10 23:39:57 toniblaster drempelbox[1365]: Playing...
Nov 10 23:39:57 toniblaster drempelbox[1365]: 2023-11-10T22:39:57.022675Z DEBUG librespot_playback::player: command=Load(SpotifyId { id: 181874502310399482585459847615985601637, audio_type: Track }, true, 0)
Nov 10 23:39:57 toniblaster drempelbox[1365]: 2023-11-10T22:39:57.028615Z DEBUG hyper::proto::h1::conn: read eof
Nov 10 23:39:57 toniblaster drempelbox[1365]: 2023-11-10T22:39:57.051347Z DEBUG librespot_core::session: Invalidating session[0]
Nov 10 23:39:57 toniblaster drempelbox[1365]: 2023-11-10T22:39:57.051520Z ERROR librespot_playback::player: Unable to load audio item: MercuryError
Nov 10 23:39:57 toniblaster drempelbox[1365]: 2023-11-10T22:39:57.051954Z ERROR librespot_playback::player: Unable to load audio item: MercuryError
Nov 10 23:39:57 toniblaster drempelbox[1365]: 2023-11-10T22:39:57.052092Z  WARN librespot_playback::player: Skipping to next track, unable to load track <SpotifyId { id: 181874502310399482585459847615985601637, audio_type: Track }>: ()
Nov 10 23:39:57 toniblaster drempelbox[1365]: 2023-11-10T22:39:57.052181Z DEBUG librespot_playback::player: drop PlayerInternal[0]
Nov 10 23:39:57 toniblaster drempelbox[1365]: 2023-11-10T22:39:57.052258Z  INFO drempelbox::spotify_player: EndOfTrack!
Nov 10 23:39:57 toniblaster drempelbox[1365]: 2023-11-10T22:39:57.052461Z DEBUG librespot_core::session: drop Dispatch
Nov 10 23:39:57 toniblaster drempelbox[1365]: 2023-11-10T22:39:57.052622Z ERROR librespot_core::session: Connection reset by peer (os error 104)
Nov 10 23:39:57 toniblaster drempelbox[1365]: 2023-11-10T22:39:57.059097Z DEBUG librespot_playback::player: PlayerInternal thread finished.
Nov 10 23:40:01 toniblaster drempelbox[1365]: 2023-11-10T22:40:01.002751Z  INFO drempelbox::server: Got stop request
Nov 10 23:40:01 toniblaster drempelbox[1365]: 2023-11-10T22:40:01.002791Z  INFO drempelbox::server: submitted stop request
Nov 10 23:40:01 toniblaster drempelbox[1365]: 2023-11-10T22:40:01.003253Z  INFO drempelbox::player: received stop request
Nov 10 23:40:01 toniblaster drempelbox[1365]: 2023-11-10T22:40:01.003294Z  INFO drempelbox::spotify_player: stopping spotify
Nov 10 23:40:01 toniblaster drempelbox[1365]: 2023-11-10T22:40:01.003329Z ERROR librespot_playback::player: Player Commands Error: channel closed

Might just have been a network glitch, this line points me to that idea: Nov 10 23:39:57 toniblaster drempelbox[1365]: 2023-11-10T22:39:57.052622Z ERROR librespot_core::session: Connection reset by peer (os error 104)

We should probably be more resilient about underlying pieces crashing and restart them if necessary. If you have an idea to repro this easily, we could start working and testing a fix/improvement.

washed commented 8 months ago

Looking at it more closely, our tasks where running just fine, but the librespot internal player died.

washed commented 6 months ago

From playing with the service file I think i now know what happened here. When you saw this, we still had a broken service definition and the service started before all the dependencies where up, specifically the actually executing user service and the sound device. I have seen the exact same behavior when i was executing the service with the new drempelbox user, but hadn't adjusted the Required and After statements. So I'd like to park this as "probably fixed" for now. If it comes up again, we can revisit!