search

wouterdebie / locast2tuner

Locast to Emby/Plex/Channels server
https://wouterdebie.github.io/locast2tuner/
MIT License
52 stars 8 forks source link

Application failed with multiple EOF exceptions from different channels #52

Closed jg-24 closed 3 years ago

jg-24 commented 3 years ago

locast2tuner 0.1.37 on Darwin 20.4.0

While watching channels (locast2tuner running via terminal on Mac) through Plex this afternoon, player failed at various times. I tried to find something in the Plex logs just to see if I could narrow down a cause and made various Plex configuration changes between restarts of locast2tuner, but there didn't seem to be anything worthwhile to add to this issue.

My gut feeling is that it was network related as my wife mentioned getting kicked out of online meetings multiple times this afternoon, which hasn't happened since we upgraded our Internet plan. We have the highest Xfinity home plan, but increasing speed doesn't necessarily make their network more stable -- so I'm sure this isn't reproducible.

Ideally, some exception handling could be added that would retry about 5 or 10 times, maybe a second apart which should be inside cached times for whatever is playing, then log the error but not kill the application. Of course, feel free to close as could not reproduce if there's really nothing that fits within the application logic.

mod.rs
559:            Ok(r) => r.bytes().await.unwrap().to_vec(),
May 19 15:03:50.460 INFO Serving https://sea.locastnet.org/proxy/sea/king_src270243638.ts (6 s) in 5.6220093s
thread 'actix-rt|system:0|arbiter:8' panicked at 'called `Result::unwrap()` on an `Err` value: reqwest::Error { kind: Body, source: hyper::Error(Body, Custom { kind: UnexpectedEof, error: IncompleteBody }) }', src/http/mod.rs:559:38

May 19 15:15:37.934 INFO Serving https://sea.locastnet.org/proxy/sea/kcpqstadium162146255.ts (10 s) in 9.654999s
May 19 15:15:47.855 INFO Stream 790cf59 - playing: segment "https://sea.locastnet.org/proxy/sea/kcpqstadium162146255.ts"
May 19 15:15:48.014 INFO Stream 790cf59 - added segment "https://sea.locastnet.org/proxy/sea/kcpqstadium162146263.ts"
May 19 15:15:48.014 INFO Serving https://sea.locastnet.org/proxy/sea/kcpqstadium162146256.ts (10 s) in 9.575001s
thread 'actix-rt|system:0|arbiter:3' panicked at 'called `Result::unwrap()` on an `Err` value: reqwest::Error { kind: Body, source: hyper::Error(Body, Custom { kind: UnexpectedEof, error: IncompleteBody }) }', src/http/mod.rs:559:38


May 19 16:02:49.028 INFO Serving https://sea.locastnet.org/proxy/sea/kcpqstadium162146538.ts (10 s) in 9.596008s
May 19 16:02:58.862 INFO Stream b4927e0 - playing: segment "https://sea.locastnet.org/proxy/sea/kcpqstadium162146538.ts"
May 19 16:02:59.003 INFO Stream b4927e0 - added segment "https://sea.locastnet.org/proxy/sea/kcpqstadium162146546.ts"
May 19 16:02:59.003 INFO Serving https://sea.locastnet.org/proxy/sea/kcpqstadium162146539.ts (10 s) in 9.619995s
thread 'actix-rt|system:0|arbiter:3' panicked at 'called `Result::unwrap()` on an `Err` value: reqwest::Error { kind: Body, source: hyper::Error(Body, Custom { kind: UnexpectedEof, error: IncompleteBody }) }', src/http/mod.rs:559:38


May 19 16:54:27.921 INFO Serving https://sea.locastnet.org/proxy/sea/kctscreate162146847.ts (10 s) in 9.553986s
May 19 16:54:37.998 INFO Stream 16c5710 - playing: segment "https://sea.locastnet.org/proxy/sea/kctscreate162146847.ts"
May 19 16:54:38.181 INFO Stream 16c5710 - added segment "https://sea.locastnet.org/proxy/sea/kctscreate162146856.ts"
May 19 16:54:38.181 INFO Serving https://sea.locastnet.org/proxy/sea/kctscreate162146848.ts (10 s) in 9.294006s
May 19 16:54:47.717 INFO Stream 16c5710 - playing: segment "https://sea.locastnet.org/proxy/sea/kctscreate162146848.ts"
May 19 16:54:47.847 INFO Stream 16c5710 - added segment "https://sea.locastnet.org/proxy/sea/kctscreate162146857.ts"
May 19 16:54:47.847 INFO Serving https://sea.locastnet.org/proxy/sea/kctscreate162146849.ts (10 s) in 9.627991s
thread 'actix-rt|system:0|arbiter:5' panicked at 'called `Result::unwrap()` on an `Err` value: reqwest::Error { kind: Body, source: hyper::Error(Body, Custom { kind: UnexpectedEof, error: IncompleteBody }) }', src/http/mod.rs:559:38
wouterdebie commented 3 years ago

This looks like a transient error and we should terminate the steam I think or retry a few times. The interesting thing here is that the http request to locast succeeds, but it's apparently incomplete. Not sure why that happened though. I'll have a look tomorrow and see what we should do here.

On Wed, May 19, 2021, 19:52 Jeff @.***> wrote:

locast2tuner 0.1.37 on Darwin

While watching channels (locast2tuner running via terminal on Mac) through Plex this afternoon, player failed at various times. I tried to find something in the Plex logs just to see if I could narrow down a cause and made various Plex configuration changes between restarts of locast2tuner, but there didn't seem to be anything worthwhile to add to this issue.

My gut feeling is that it was network related as my wife mentioned getting kicked out of online meetings multiple times this afternoon, which hasn't happened since we upgraded our Internet plan. We have the highest Xfinity home plan, but increasing speed doesn't necessarily make their network more stable -- so I'm sure this isn't reproducible.

Ideally, some exception handling could be added that would log the error but not kill the application, but feel free to close as could not reproduce if there's really nothing that fits within the application logic.

May 19 15:03:50.460 INFO Serving https://sea.locastnet.org/proxy/sea/king_src270243638.ts (6 s) in 5.6220093s thread 'actix-rt|system:0|arbiter:8' panicked at 'called Result::unwrap() on an Err value: reqwest::Error { kind: Body, source: hyper::Error(Body, Custom { kind: UnexpectedEof, error: IncompleteBody }) }', src/http/mod.rs:559:38

May 19 15:15:37.934 INFO Serving https://sea.locastnet.org/proxy/sea/kcpqstadium162146255.ts (10 s) in 9.654999s May 19 15:15:47.855 INFO Stream 790cf59 - playing: segment "https://sea.locastnet.org/proxy/sea/kcpqstadium162146255.ts" May 19 15:15:48.014 INFO Stream 790cf59 - added segment "https://sea.locastnet.org/proxy/sea/kcpqstadium162146263.ts" May 19 15:15:48.014 INFO Serving https://sea.locastnet.org/proxy/sea/kcpqstadium162146256.ts (10 s) in 9.575001s thread 'actix-rt|system:0|arbiter:3' panicked at 'called Result::unwrap() on an Err value: reqwest::Error { kind: Body, source: hyper::Error(Body, Custom { kind: UnexpectedEof, error: IncompleteBody }) }', src/http/mod.rs:559:38

May 19 16:02:49.028 INFO Serving https://sea.locastnet.org/proxy/sea/kcpqstadium162146538.ts (10 s) in 9.596008s May 19 16:02:58.862 INFO Stream b4927e0 - playing: segment "https://sea.locastnet.org/proxy/sea/kcpqstadium162146538.ts" May 19 16:02:59.003 INFO Stream b4927e0 - added segment "https://sea.locastnet.org/proxy/sea/kcpqstadium162146546.ts" May 19 16:02:59.003 INFO Serving https://sea.locastnet.org/proxy/sea/kcpqstadium162146539.ts (10 s) in 9.619995s thread 'actix-rt|system:0|arbiter:3' panicked at 'called Result::unwrap() on an Err value: reqwest::Error { kind: Body, source: hyper::Error(Body, Custom { kind: UnexpectedEof, error: IncompleteBody }) }', src/http/mod.rs:559:38

May 19 16:54:27.921 INFO Serving https://sea.locastnet.org/proxy/sea/kctscreate162146847.ts (10 s) in 9.553986s May 19 16:54:37.998 INFO Stream 16c5710 - playing: segment "https://sea.locastnet.org/proxy/sea/kctscreate162146847.ts" May 19 16:54:38.181 INFO Stream 16c5710 - added segment "https://sea.locastnet.org/proxy/sea/kctscreate162146856.ts" May 19 16:54:38.181 INFO Serving https://sea.locastnet.org/proxy/sea/kctscreate162146848.ts (10 s) in 9.294006s May 19 16:54:47.717 INFO Stream 16c5710 - playing: segment "https://sea.locastnet.org/proxy/sea/kctscreate162146848.ts" May 19 16:54:47.847 INFO Stream 16c5710 - added segment "https://sea.locastnet.org/proxy/sea/kctscreate162146857.ts" May 19 16:54:47.847 INFO Serving https://sea.locastnet.org/proxy/sea/kctscreate162146849.ts (10 s) in 9.627991s thread 'actix-rt|system:0|arbiter:5' panicked at 'called Result::unwrap() on an Err value: reqwest::Error { kind: Body, source: hyper::Error(Body, Custom { kind: UnexpectedEof, error: IncompleteBody }) }', src/http/mod.rs:559:38

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/wouterdebie/locast2tuner/issues/52, or unsubscribe https://github.com/notifications/unsubscribe-auth/AABKABUPITQ3AMWTI6NTQPTTORML5ANCNFSM45FY5GZA .

jg-24 commented 3 years ago

I recall many times troubleshooting similar networking issues with an application I made that about half the airplanes built in the last 10 years use to talk to "ground systems" and there's almost never a way to find an exact cause. One of the symptoms was always items that didn't download completely (EOF exceptions when parsing) even though there were other indicators that the connection was still established and responsive. Ultimately, I usually ended up picking a configurable retry window (with a little bit of fixed or variable time between tries) then either ended that processing attempt or bubbled up an exception.

For what it's worth, as of this morning (overnight and 3 hours of watching locast programming this morning) locast2tuner has been running fine after the last error reported above.

wouterdebie commented 3 years ago

Yeah, something that might have happened is that the HTTP request itself succeeded (i.e. HTTP 200), but the content that was served was less than the Length: header. I'll actually stop the stream, rather than panicking, since there isn't much time to retry. Locast2tuner doesn't buffer any of the data that is fetched from locast, so a retry wouldn't really help.