Jump to content

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


Recommended Posts

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.

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.

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!

 

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?

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

Posted

OK try the latest build and see if that segment is severed now. Thanks

vdatanet
Posted

I tried the latest build — 4.10.0.29, the current beta tag. Same setup as my codecs
measurements in the other thread: a fresh install in a disposable container, nothing carried
over from my server. Two sources: a real 21-minute TV episode (MKV, h264 + AC-3, 906 MB)
that has been failing at the end for me for a year, and synthetic MKVs built for the
purpose. Everything below comes from the server's own log and from the files in its
transcoding-temp directory.

The short answer: the segment is not served yet. But I can now show exactly where it stops,
and the arithmetic and the stuck tail turn out to be two halves of one mechanism.

1) The list is still computed from the declared duration.

The episode's container declares 1269.280 s; its last video packet is stamped 1268.184 s
(ffprobe, read to EOF). The playlist the beta serves:

    212 segments, all #EXTINF:6.0000  ->  1272.00 s promised

That is the declared duration rounded up to whole segments — about 3.8 s promised past the
last frame. A 60-second synthetic MKV whose Segment Info duration I patched to 90 s gets
15 × 6.0 s; re-encoded it gets 30 × 3.0 s. Always the declared 90, never the real 60.

2) The tail on the real episode (video copied, fMP4 segments), step by step:

    - during the remux: segments 0, 106, 210  ->  all 200
    - ffmpeg finishes on its own; the transcoding-temp directory holds all 212 segment
      files, 211 included
    - GET segment 211  ->  the request never completes. The server held it for 90 seconds
      until my client gave up. Its own log, one request id end to end:

        21:05:07.760  GET .../hls1/main/211.mp4
        21:05:07.760  Starting transcoding because currentTranscodingIndex=null
        21:05:07.856  ProcessRun 'StreamTranscode 011ceb' Process exited with code 0
        21:06:37.769  Response completed after client disconnected. Time: 90009ms

The file it was asked for was complete on disk before the request arrived, and the ffmpeg
restarted to produce it exited cleanly 96 ms in. The response never came.

3) The same thing as a 500 instead of a hang, on the patched synthetic (30 segments
promised, 20 producible): after ffmpeg's clean exit, segment 19 — real, sitting on disk —
returns 500. So do 20 and 29, and every retry. The 500 body is

    FfRunException: Error starting ffmpeg

wrapping an ffmpeg log that ends in a normal, complete run with exit code 0.

And the extreme case, which takes the declared duration out of the picture entirely: a 3 MB
MKV with an honest 60-second duration remuxes in about 25 ms — faster than the startup
watchdog — and every segment request, init.mp4 included, returns that same 500, forever.

So what it looks like from the outside: segment availability is decided from the state of
the transcoding process, not from what is in the transcoding directory. While ffmpeg is
alive, everything serves. Once it has exited — and near the end of the media it exits
quickly, because there is little left to do — a clean exit is read as "Error starting
ffmpeg", or, on the fMP4 path, the last segment waits on a completion signal from a process
that is already gone. The declared-duration arithmetic then guarantees that every player
ends its session inside exactly that zone — which I believe is this thread, the step-back
500s on a segment that had been served 200 minutes earlier, the sessions stuck at end of
file, and the streams that never end server-side, all at once.

At the moment of every 500 and of the hang above, everything needed was already on disk:
the segment file, ffmpeg's own playlist with ENDLIST, exit code 0. If the wait checked the
directory before concluding, and treated a clean exit as completion rather than as a
startup failure, I believe every case above would serve.

If the segment fix wasn't meant to be in 4.10.0.29 yet, happy to rerun all of this against
the next build — the whole setup takes a few minutes and none of it touches my real server.

vdatanet
Posted

Following up on my own post, because I went back for the ffmpeg logs afterwards and they
contain the mechanism. I attached them (ffmpeg-segment-211.txt — two runs from the same
session, sanitised as described in its header).

Short version: ffmpeg announces a segment when it opens the NEXT one, so the last segment
of any run is never announced — and from the outside it looks like that announcement is
what releases a segment to the client.

The announcement lines look like this:

    SegmentComplete=video:0 Index=211 ... Duration=6.027000 filename=C7DAFF_210.mp4

Index=N+1 announcing filename=_N.mp4. Here are three requests from one session, on the
21-minute file from my last post, whose playlist has 212 entries (0..211):

    segment 106  ->  full remux, no seek        212 SegmentComplete lines   200
    segment 210  ->  full remux, no seek        211 lines, last announces _210.mp4   200
    segment 211  ->  restart with -ss 00:21:06.000 -start_number 211
                                                ZERO SegmentComplete lines  never answered

Across every ffmpeg log this server wrote, filename=C7DAFF_211.mp4 appears in zero
SegmentComplete lines. C7DAFF_210.mp4 appears in one. Even the full remux that did write
211 ends like this:

    21:04:59.046 SegmentComplete=... filename=C7DAFF_210.mp4
    [hls] Opening '.../C7DAFF_211.mp4.tmp' for writing
    [hls] Opening '.../C7DAFF.m3u8.tmp' for writing
    EXIT

It opens 211 and the run ends without announcing it.

And the restart for 211 did its job: it wrote C7DAFF_211.mp4 — 1,657,212 bytes, 134 frames,
5.494 s — in about 10 ms at 361x, rewrote the session playlist with that one entry AND an
#EXT-X-ENDLIST, and exited with code 0, 96 ms after the request arrived. ffmpeg declared
the work finished in its own playlist. The server then held the request for 90 seconds and
sent nothing.

Two corrections I owe you on my own post from yesterday.

First, I said the wait was for a completion signal "from a process that is already gone".
The process being gone is not the cause: the signal is never emitted for the last segment
of a run, whether the process is alive or dead.

Second, I implied the restarts themselves were the problem. They aren't — segments 106 and
210 went through exactly the same restart path minutes earlier and both returned 200. What
saves them is that the run continued past them, so they got announced.

Which also ties this to the arithmetic at the top of the thread, and I think it's the whole
bug in one sentence: because the segment list is computed from the declared duration, the
last entry always sits at or past the end of the media, so it is always the final segment
of whatever run produces it — and the final segment of a run is never announced. The same
shape explains the 500s on short files: when the whole remux takes milliseconds, every
segment requested is the last one of its run.

If the wait treated EOF — or an exit code of 0, or ffmpeg's own ENDLIST, all three of which
are present here — as completing the final segment, I believe every case in this thread
would serve. The file is already on disk when the wait begins.

Happy to run this against the next build, or to pull any other log from the same session.

ffmpeg-segment-211.txt

Posted

What about the 220 segment? Not the last one.

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...