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.

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

stream.hls: Add warning when segments expire from playlist before being queued #5603

Closed
3 tasks done
Hakkin opened this issue Oct 10, 2023 · 3 comments · Fixed by #5607
Closed
3 tasks done

stream.hls: Add warning when segments expire from playlist before being queued #5603

Hakkin opened this issue Oct 10, 2023 · 3 comments · Fixed by #5607

Comments

@Hakkin
Copy link
Contributor

Hakkin commented Oct 10, 2023

Checklist

Description

Today my internet briefly went out while using streamlink to record an HLS stream, but came back up about a minute later. When it came back, it started downloading segments again, but I was surprised to see in the log that it simply skipped from segment 143 to 174 without any kind of log message indicating any issue. I had actually thought that streamlink output a warning when things like that occurred, but I realize now I was probably thinking of ffmpeg.
ffmpeg has a warning for when this situation occurs here:
https://github.com/FFmpeg/FFmpeg/blob/c06d3d24047206f9c11bfc5849544b960e5d68eb/libavformat/hls.c#L1518-L1523

It would be nice if streamlink could output a similar warning if it encounters non-consecutive sequence numbers. This wouldn't just be useful for internet issues but also potentially as an indicator that the --hls-playlist-reload-time needs to be set. I have occasionally encountered misbehaving HLS producers with wildly incorrect EXT-X-TARGETDURATION values causing segments to expire between playlist refreshes, but wouldn't necessarily have noticed any issue if I was just looking at the current log output.

@bastimeyer
Copy link
Member

it simply skipped from segment 143 to 174 without any kind of log message

Streamlink should log error messages on failed segment requests/resposes:

  • def fetch(self, segment: HLSSegment) -> Optional[Response]:
    try:
    return self._fetch(
    segment.uri,
    stream=self.stream_data,
    **self.create_request_params(segment.num, segment, False),
    )
    except StreamError as err:
    log.error(f"Failed to fetch segment {segment.num}: {err}")
  • try:
    for chunk in result.iter_content(self.WRITE_CHUNK_SIZE):
    self.reader.buffer.write(chunk)
    except (ChunkedEncodingError, ContentDecodingError, ConnectionError) as err:
    log.error(f"Download of segment {segment.num} failed: {err}")
    return

When it came back, it started downloading segments again

HLS streams always continue despite segment errors, because it can be recovered from in most cases, even though it's a stream discontinuity. While this is bad for recording streams, it at least keeps live streams alive, which is the intention here and the main purpose of Streamlink. Recording is always an afterthought. Streamlink does only stop when the buffer timeout triggers (--stream-timeout - default is 60 seconds), meaning when the last RingBuffer.read() call times out due to missing data.

So if your connection came back before the stream timeout triggered, it should've logged error messages due to failed segment requests or failed playlist reloads. This of course depends on the timeout value you've set for individual HTTP requests (--http-timeout - default is 20 seconds). This affects both HTTP request connection timeouts and read timeouts for in-flight HTTP responses, but it's handled by requests, and not by Streamlink.

Did you change any HTTP options or the log output level?

Btw, annotated stream discontinuities get logged.

@Hakkin
Copy link
Contributor Author

Hakkin commented Oct 10, 2023

Streamlink should log error messages on failed segment requests/resposes:

Did you change any HTTP options or the log output level?

My options were

[cli][debug]  --retry-streams=5.0
[cli][debug]  --retry-max=12
[cli][debug]  --retry-open=10
[cli][debug]  --stream-segment-attempts=20
[cli][debug]  --stream-segment-threads=10
[cli][debug]  --stream-segment-timeout=60.0
[cli][debug]  --stream-timeout=240.0
[cli][debug]  --hls-playlist-reload-attempts=10
[cli][debug]  --hls-playlist-reload-time=segment
[cli][debug]  --hls-live-restart=True

and here's the relevant log section:

[02:56:08.176680][stream.hls][debug] Reloading playlist
[02:56:08.195682][stream.hls][debug] Adding segment 121 to queue
[02:56:08.243686][stream.hls][debug] Writing segment 121 to output
[02:56:08.245687][stream.hls][debug] Segment 121 complete
[02:56:10.164879][stream.hls][debug] Reloading playlist
[02:56:30.777982][stream.hls][debug] Adding segment 122 to queue
[02:56:30.777982][stream.hls][debug] Adding segment 123 to queue
[02:56:30.777982][stream.hls][debug] Adding segment 124 to queue
[02:56:30.778982][stream.hls][debug] Adding segment 125 to queue
[02:56:30.779983][stream.hls][debug] Adding segment 126 to queue
[02:56:30.783983][stream.hls][debug] Adding segment 127 to queue
[02:56:30.787983][stream.hls][debug] Adding segment 128 to queue
[02:56:30.791984][stream.hls][debug] Adding segment 129 to queue
[02:56:30.793984][stream.hls][debug] Adding segment 130 to queue
[02:56:30.799985][stream.hls][debug] Adding segment 131 to queue
[02:56:30.800985][stream.hls][debug] Adding segment 132 to queue
[02:56:30.801985][stream.hls][debug] Reloading playlist
[02:56:31.809098][stream.hls][debug] Reloading playlist
[02:56:33.339251][stream.hls][debug] Adding segment 133 to queue
[02:56:33.802297][stream.hls][debug] Reloading playlist
[02:56:33.911308][stream.hls][debug] Adding segment 134 to queue
[02:56:35.814500][stream.hls][debug] Reloading playlist
[02:56:35.901509][stream.hls][debug] Adding segment 135 to queue
[02:56:37.802699][stream.hls][debug] Reloading playlist
[02:56:37.982717][stream.hls][debug] Adding segment 136 to queue
[02:56:39.812900][stream.hls][debug] Reloading playlist
[02:56:40.122931][stream.hls][debug] Adding segment 137 to queue
[02:56:41.803099][stream.hls][debug] Reloading playlist
[02:56:41.924111][stream.hls][debug] Adding segment 138 to queue
[02:56:43.802299][stream.hls][debug] Reloading playlist
[02:56:43.863305][stream.hls][debug] Adding segment 139 to queue
[02:56:45.814500][stream.hls][debug] Reloading playlist
[02:56:45.966516][stream.hls][debug] Adding segment 140 to queue
[02:56:47.802699][stream.hls][debug] Reloading playlist
[02:56:47.892708][stream.hls][debug] Adding segment 141 to queue
[02:56:49.809900][stream.hls][debug] Reloading playlist
[02:56:49.953914][stream.hls][debug] Adding segment 142 to queue
[02:56:51.803099][stream.hls][debug] Reloading playlist
[02:56:52.116130][stream.hls][debug] Adding segment 143 to queue
[02:58:16.990940][stream.hls][debug] Writing segment 122 to output
[02:58:17.003443][stream.hls][debug] Segment 122 complete
[02:58:17.003943][stream.hls][debug] Writing segment 123 to output
[02:58:17.007944][stream.hls][debug] Segment 123 complete
[02:58:17.008944][stream.hls][debug] Reloading playlist
[02:58:17.323004][stream.hls][debug] Adding segment 172 to queue
[02:58:17.323505][stream.hls][debug] Adding segment 173 to queue
[02:58:18.589744][stream.hls][debug] Writing segment 124 to output
[02:58:18.592745][stream.hls][debug] Segment 124 complete
[02:58:18.593745][stream.hls][debug] Writing segment 125 to output
[02:58:18.598746][stream.hls][debug] Segment 125 complete
[02:58:18.599246][stream.hls][debug] Writing segment 126 to output
[02:58:18.599246][stream.hls][debug] Adding segment 174 to queue
[02:58:18.626752][stream.hls][debug] Segment 126 complete
[02:58:18.654257][stream.hls][debug] Writing segment 127 to output
[02:58:18.650757][stream.hls][debug] Adding segment 175 to queue
[02:58:18.660258][stream.hls][debug] Segment 127 complete
[02:58:18.675761][stream.hls][debug] Writing segment 128 to output
[02:58:18.675261][stream.hls][debug] Adding segment 176 to queue
[02:58:18.679762][stream.hls][debug] Segment 128 complete
[02:58:18.733273][stream.hls][debug] Adding segment 177 to queue
[02:58:18.733273][stream.hls][debug] Writing segment 129 to output
[02:58:18.741275][stream.hls][debug] Adding segment 178 to queue
[02:58:18.745776][stream.hls][debug] Segment 129 complete
[02:58:18.753277][stream.hls][debug] Writing segment 130 to output
[02:58:18.754777][stream.hls][debug] Segment 130 complete
[02:58:18.756778][stream.hls][debug] Writing segment 131 to output
[02:58:18.759278][stream.hls][debug] Segment 131 complete
[02:58:18.759778][stream.hls][debug] Adding segment 179 to queue
[02:58:18.825292][stream.hls][debug] Adding segment 180 to queue
[02:58:18.825292][stream.hls][debug] Adding segment 181 to queue
[02:58:18.760278][stream.hls][debug] Writing segment 132 to output
[02:58:18.831293][stream.hls][debug] Segment 132 complete
[02:58:18.838794][stream.hls][debug] Writing segment 133 to output
[02:58:18.842795][stream.hls][debug] Segment 133 complete
[02:58:18.843795][stream.hls][debug] Adding segment 182 to queue
[02:58:18.846796][stream.hls][debug] Writing segment 134 to output
[02:58:18.847296][stream.hls][debug] Adding segment 183 to queue
[02:58:18.850296][stream.hls][debug] Segment 134 complete
[02:58:18.876802][stream.hls][debug] Writing segment 135 to output
[02:58:18.883303][stream.hls][debug] Adding segment 184 to queue
[02:58:18.887804][stream.hls][debug] Segment 135 complete
[02:58:18.888804][stream.hls][debug] Writing segment 136 to output
[02:58:18.891805][stream.hls][debug] Segment 136 complete
[02:58:18.892805][stream.hls][debug] Writing segment 137 to output
[02:58:18.899306][stream.hls][debug] Segment 137 complete
[02:58:18.899306][stream.hls][debug] Writing segment 138 to output
[02:58:18.912309][stream.hls][debug] Segment 138 complete
[02:58:18.912809][stream.hls][debug] Adding segment 185 to queue
[02:58:18.912809][stream.hls][debug] Writing segment 139 to output
[02:58:18.938314][stream.hls][debug] Segment 139 complete
[02:58:18.938814][stream.hls][debug] Writing segment 140 to output
[02:58:18.941314][stream.hls][debug] Segment 140 complete
[02:58:18.943815][stream.hls][debug] Writing segment 141 to output
[02:58:18.948316][stream.hls][debug] Segment 141 complete
[02:58:18.951317][stream.hls][debug] Writing segment 142 to output
[02:58:18.953817][stream.hls][debug] Segment 142 complete
[02:58:18.954317][stream.hls][debug] Writing segment 143 to output
[02:58:18.957318][stream.hls][debug] Segment 143 complete
[02:58:18.958318][stream.hls][debug] Writing segment 172 to output
[02:58:18.963819][stream.hls][debug] Segment 172 complete
[02:58:19.066339][stream.hls][debug] Reloading playlist

So all the queued segments actually completed fine eventually (within the timeout period), there was just a period where the playlist request hung (due to my internet going out), and during that period obviously the playlist segments keep getting appended and removed, so when the request finally went through, a lot of segments were "missed". It's those "missed" segments that I'm requesting a warning about, similar to the ffmpeg one.

For example, for this case, streamlink did a playlist refresh and saw a maximum segment number of 143, then in the next playlist refresh (that happened to be much later than expected because of network issues), the lowest segment number was 172. If the lowest segment number of the new playlist is greater than the maximum of the old playlist + 1, then we've "dropped" segments between refreshes. This is what I want a warning about. If we go based on the ffmpeg warning, it would be [warning] Skipping 28 segments ahead, expired from playlists in this case. Personally I don't really like that warning, I think it could be more descriptive, but just some kind of indicator that segments were missed between playlist refreshes would be nice.

@bastimeyer
Copy link
Member

We can add such a warning, similar to the warning of the annotated discontinuities.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants