Jump to content

HLS segment list is computed from the container's declared duration and is never checked against the media.


Recommended Posts

vdatanet
Posted

Emby Server 4.9.5.0 (Linux, .NET 8).

The claim: the HLS segment list is computed from the container's declared duration and is never checked against the media. For any file whose declared duration runs past its last frame, the list therefore always contains one trailing segment that cannot be produced.

It reproduces in one request

No playback, no transcoding session to watch, no waiting for the end of a file — just fetch the variant playlist and count:

curl -s "<server>/emby/videos/<id>/main.m3u8?<params>" | grep -c '#EXTINF'

curl -s "<server>/emby/videos/<id>/main.m3u8?<params>" \
  | grep -o '#EXTINF:[0-9.]*' | cut -d: -f2 | awk '{s+=$1} END {print s}'

For a 22-minute MKV here (RunTimeTicks 13263360000 = 1326.336 s), 6-second segments:

Segments in the list 222 (0–221)
Distinct #EXTINF values one  6.0000, all 222 times
Sum of declared durations 1332.000 s
Declared container duration 1326.336 s
End of the written media 1325.365 s

That last figure is the server's own, from SegmentComplete=video:0 Index=220 Start=0.000000 End=1325.365000. So the playlist advertises 6.635 s of video that does not exist, and the trailing segment is declared 6.0000 rather than the 0.336 s it would nominally cover. #EXT-X-TARGETDURATION is 7 while every segment says 6.

What follows from it

When a client asks for that trailing segment, ffmpeg is started with -ss 00:22:06.000, which is past the last frame. What happens next depends on the path:

  • Copy / remux (-c:v copy -c:a copy😞 ffmpeg exits 0 having written nothing, and the request is answered 500. Clients retry indefinitely; each retry starts a new ffmpeg process.
  • Transcode (hevc_vaapi😞 the encoder gets no frames and segfaults  Process exited with code 139 - Failed. The request is never answered at all; the connection is held open until the client disconnects.

Either way the stream never terminates, so no client on the HLS path ever reaches end-of-stream. Direct play is unaffected, because it never reads the segment list.

Why this is posted here

This is not a configuration issue and it does not depend on the client. The symptom side — sessions stuck on the dashboard, next episode not starting — is already reported at 145772, with the playback-side measurements. This post is only about the arithmetic that builds the list.

Deriving the segment count and the final #EXTINF from the actual end of the media rather than from RunTimeTicks would remove the phantom segment, and would also make the last segment's declared duration honest. Happy to provide the full playlist, the server log or the sample file.

vdatanet
Posted

One last thing, and I say it with a smile.

This is the bug that is pushing me to demux Matroska on the Apple TV myself. The app already carries a Matroska demuxer and an fMP4 muxer — I wrote them to keep HDR intact end to end — and the arithmetic above is what is now making me point them at everything else, HDR or not, so that the player never has to ask for a segment list at all. A playlist I never request cannot promise me a segment that was never written.

For a TV app this one really is fatal: an episode that never reaches its end is an episode that never starts the next one, and a session left open on your dashboard. So I route around it — but writing container plumbing is not what a client should be spending its time on. It's a lot of code to own, a lot of new surface for bugs that are entirely mine, and every hour of it is an hour not spent on the app itself. I would delete all of it, gladly and in a single commit, the day the server hands me a stream I can play straight through.

That's all this report is really asking for. Happy to test anything you want tested.

Posted

This could be made more accurate by scanning the file for keyframe information during import. The problem is that this can take a long time, so that’s why this is a prediction.

vdatanet
Posted

Thanks — I went to test that, and the result surprised me.

If the list were approximating keyframe positions, changing the keyframe-break request ought to change it. It doesn't. Same file, same parameters, only BreakOnNonKeyFrames varying:

BreakOnNonKeyFrames=True     222 segments, all #EXTINF:6.0000, sum 1332.000
(parameter absent)           222 segments, all #EXTINF:6.0000, sum 1332.000
BreakOnNonKeyFrames=False    222 segments, all #EXTINF:6.0000, sum 1332.000

The three playlists are byte-identical once the PlaySessionId is stripped. And the count is exactly ceil(declared duration / segment length), at both lengths I can get the server to produce:

ceil(1326.336 / 6) = 222  ->  1332.000 s advertised
ceil(1326.336 / 3) = 443  ->  1329.000 s advertised

So the list isn't an imprecise estimate of where keyframes fall — it doesn't consult them at all, and every entry carries the nominal segment length rather than a measured one. That's why I don't think an import-time scan is what's missing here: making the last entry honest doesn't need keyframe positions, only the end of the media. And the gap isn't boundary rounding, it's 6.6 s — a whole segment.

And the failure isn't confined to the predicted segment

When the player doesn't get 221, it steps back to 220. That one is not predicted: it is real, it is inside the media, and it had already been served 200 earlier in the same session. It gets 500 nine times as well.

One of those requests, end to end — 93 ms:

14:53:00.573  GET .../hls1/main/220.ts
14:53:00.614  ProcessRun 'StreamTranscode c2b692' Execute: ... -ss 00:22:00.000 ...
                                                  -segment_start_number 220
14:53:00.628  SegmentComplete=video:0 Index=220 ... Frames=136 filename=04C768_220.ts
14:53:00.628  video:2332kB audio:148kB subtitle:0kB other streams:0kB
14:53:00.628  EXIT
14:53:00.634  ProcessRun 'StreamTranscode c2b692' Process exited with code 0
14:53:00.666  Error processing request
14:53:00.666  Response 500

ffmpeg produced the segment — 136 frames, 6.72 s, 2.4 MB — and exited 0. The request was answered 500 anyway. So there is a second failure that a better prediction would not fix, and it is the one that makes this unrecoverable: the client cannot get out of it even by stepping back to a segment that exists.

Possibly related, from that same line: SegmentComplete reports Index=220 with Start=0.000000 End=1325.365000 Duration=1325.365000 — the length of the whole episode, for a segment holding 6.72 s. The command line carries -segment_time_delta -00:22:00.000 together with -copyts -start_at_zero. If anything downstream checks the produced segment against an expected time, that bookkeeping wouldn't match. I don't know the code, so this is only a guess.

The transcoding path is a third thing again: there hevc_vaapi exits 139 (SIGSEGV) five times in forty seconds, and the request is never answered at all.

None of this needs the prediction to become exact. Even leaving it as it is, overshooting by one segment could end the stream rather than start an unbounded retry loop — which is what turns a third of a second of missing video into a session that never finishes.

Posted
Quote

 

When the player doesn't get 221, it steps back to 220. That one is not predicted: it is real, it is inside the media, and it had already been served 200 earlier in the same session. It gets 500 nine times as well.

Hi there, please attach the Emby server log from when the problem occurred:

Thanks!

 

vdatanet
Posted
26 minutes ago, Luke said:

Hi there, please attach the Emby server log from when the problem occurred

Attached: an annotated excerpt of embyserver.txt from that session. I trimmed it to the one
failing playback plus one contrasting session, and collapsed the repeated 500s; the header says
exactly what was cut. The full untouched log and the ffmpeg logs are yours whenever you want them.

Two things in it are worth your time.

1) THE 500 IS NOT ABOUT THE MISSING SEGMENT

221 is the phantom the arithmetic promises. When the player doesn't get 221, it steps back to 220.
That one is not predicted: it is real, it is inside the media, and it had already been served 200
earlier in the same session — 14:51:50, Content-Length 2,169,708, in 43 ms. It gets 500 nine times
as well. Eighteen 500s in total, and then the server times the session out itself.

2) THE SERVER REPORTS "ERROR STARTING FFMPEG" FOR AN FFMPEG THAT RAN AND EXITED 0

The whole of that request for 220, in 93 milliseconds:

    14:53:00.573  GET .../hls1/main/220.ts
    14:53:00.614  ProcessRun 'StreamTranscode c2b692' Execute: ... -ss 00:22:00.000 ...
    14:53:00.628  SegmentComplete=video:0 Index=220 ... Frames=136 filename=04C768_220.ts
    14:53:00.628  video:2332kB audio:148kB subtitle:0kB other streams:0kB
    14:53:00.628  EXIT
    14:53:00.634  ProcessRun 'StreamTranscode c2b692' Process exited with code 0
    14:53:00.666  Error processing request
                  FfRunException: Error starting ffmpeg
                     at BaseStreamingService.StartFfMpeg(...)
                     at DynamicHlsService.GetDynamicSegment(...)
    14:53:00.666  Response 500

The process started, wrote 136 frames / 6.72 s / 2,332 kB, and exited cleanly twenty milliseconds
after it was launched — and StartFfMpeg threw "Error starting ffmpeg" over it. The ffmpeg output
quoted inside your own error report is the evidence against the error report.

One observation, offered as an observation and not a diagnosis. In this log the segments that work
and the segments that 500 differ in exactly one respect. Segments 209 through 220 were all served
out of a single ffmpeg that was already running — none of them has a "Starting transcoding" line.
Every request that 500s is one where "Starting transcoding because currentTranscodingIndex=null"
launched a fresh process, and that process, with only the tail of the file left to write, finished
in 18–20 ms. All of those exit 0, and all of those answer 500. If whatever StartFfMpeg waits on
assumes the process is still alive by the time it looks, a run that short would fail that check no
matter how well it went. Easy to falsify from your side, and I haven't tried to guess further than
the log goes.

Why this matters beyond the arithmetic: if the playlist were clamped to the real end of the media
tomorrow, this second failure would still be here — and it is the one that leaves a client with
nowhere to go, because it cannot recover by falling back to a segment that does exist.

One correction to my own post while I'm here. I said segment 221 is never written. On this run it
is: ffmpeg is launched with -ss 00:22:06.000 -noaccurate_seek, which lands back on the keyframe at
22:00, so it writes a 221.ts holding the same 136 frames that 220 already holds. It still answers
500. The playlist entry still has no media of its own behind it — but I was wrong about the file.

The end of the excerpt has the same episode played by Emby Web with 3-second segments, where the
list runs to 442 — ceil(1326.336 / 3) = 443. The last index isn't served there either; that one
dies with ffmpeg exit code 139, five times in a row.

A small note on the cheap half of this, since the objection to fixing the list was the cost of
scanning. Both of these are arithmetic on the runtime you already have, and neither needs to know
where a keyframe falls:

    whole     = declared_duration / segment_length     (integer division)
    remainder = declared_duration % segment_length

For this file, 221 whole segments and a remainder of 0.336 s.

  * Give the last #EXTINF that remainder instead of a flat 6.0000. The playlist would promise
    1326.336 s instead of 1332.000 — the overshoot drops from 6.635 s to 0.971 s — and
    #EXT-X-TARGETDURATION:7 would stop contradicting 222 lines that all say 6.
  * If the remainder is below some minimum, don't emit that entry at all. Here 0.336 s is well
    under any sane floor, so the list would end at 220 and the player would never ask for 221,
    never step back to 220, and never meet either failure.

The first on its own only makes the manifest honest — 221 would still be promised and would still
500. It is the second that removes the symptom.

Happy to run anything you want run.

embyserver-excerpt-149368.txt

Posted

is the 220 segment in the transcode temp directory?

vdatanet
Posted
7 minutes ago, Luke said:

is the 220 segment in the transcode temp directory?

Yes — and in the same directory throughout. Everything in that session, the run that works and the
runs that fail, writes to /var/lib/emby/transcoding-temp/04C768/.

04C768_220.ts is written there twice. First by the run that serves it:

    14:51:48.772  ProcessRun 'StreamTranscode b8bdc3' Execute: ... -ss 00:20:54.000
                                                      ... -segment_start_number 209
    14:51:48.901  Process exited with code 0
    14:51:50.021  GET .../hls1/main/220.ts
    14:51:50.064  Response 200. Time: 43ms. Content-Length: 2,169,708

That run wrote 209 through 220 in 129 ms and exited. Seventy seconds later, same index, same
directory:

    14:53:00.614  ProcessRun 'StreamTranscode c2b692' Execute: ... -ss 00:22:00.000
                                                      ... -segment_start_number 220
    14:53:00.628  SegmentComplete=video:0 Index=220 ... filename=04C768_220.ts
    14:53:00.628  video:2332kB audio:148kB
    14:53:00.634  Process exited with code 0
    14:53:00.666  Response 500

So by the server's own account it is there, and it was written again on the way to the 500. What
the log cannot tell me is whether the file survived on disk between 14:51:50 and 14:53:00, and I
think that is the half your question actually turns on. I can't answer that from a log, but I can
answer it with an ls: this reproduces on demand and the failing window is a comfortable 45 seconds
of retries. Tell me what you want listed and I'll run it and paste the output raw.

Two corrections while I'm here, both mine.

The "File Deleted" line is a red herring and I should have checked it before it went near this
thread. It is AppendExtraLogData removing its own graph file (ffmpeg-directstream-...graph.txt),
and it appears identically on the run that served 200s. Nothing to do with segments.

And I overstated something in my last post. I said segments 209-220 have no "Starting transcoding"
line. The first request for 209 does:

    14:51:48.762  GET .../209.ts
    14:51:48.762  Starting transcoding because currentTranscodingIndex=null
    14:51:48.772  ProcessRun 'StreamTranscode b8bdc3' Execute: ...
    14:51:48.831  Response completed after client disconnected. Time: 69ms.
    14:51:48.901  Process exited with code 0
    14:51:48.930  GET .../209.ts          (the player asks again)
    14:51:48.997  Response 200. Time: 67ms.

The excerpt I attached starts just after that, at 14:51:48.930. That was careless rather than
deliberate, the full log has it, and I would rather point at it myself.

It also makes the pattern cleaner than I had it, so it costs me nothing to fix. It is not that the
working segments never start an ffmpeg. It is that no request which starts its own ffmpeg has ever
come back with the segment: the first 209, then 221 nine times, then 220 nine times. 209 only
succeeded because the player asked again and the file was already on disk by then. At the tail,
asking again does not help — every retry starts another process, every process writes the file and
exits 0, and every one of them still answers 500.

I have re-attached the excerpt with those lines put back in.

embyserver-excerpt-149368.txt

Create an account or sign in to comment

You need to be a member in order to leave a comment

Create an account

Sign up for a new account in our community. It's easy!

Register a new account

Sign in

Already have an account? Sign in here.

Sign In Now
×
×
  • Create New...