vdatanet 1674 Posted yesterday at 04:22 PM Posted yesterday at 04:22 PM 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 1674 Posted yesterday at 05:25 PM Author Posted yesterday at 05:25 PM 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.
Luke 42977 Posted yesterday at 05:42 PM Posted yesterday at 05:42 PM 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 1674 Posted yesterday at 06:01 PM Author Posted yesterday at 06:01 PM 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.
Luke 42977 Posted yesterday at 06:16 PM Posted yesterday at 06:16 PM 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: How to Report a Problem Thanks!
vdatanet 1674 Posted yesterday at 06:53 PM Author Posted yesterday at 06:53 PM 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
Luke 42977 Posted yesterday at 07:04 PM Posted yesterday at 07:04 PM is the 220 segment in the transcode temp directory?
vdatanet 1674 Posted yesterday at 07:29 PM Author Posted yesterday at 07:29 PM 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
Luke 42977 Posted 1 hour ago Posted 1 hour ago OK try the latest build and see if that segment is severed now. Thanks
vdatanet 1674 Posted 48 minutes ago Author Posted 48 minutes ago 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 1674 Posted 21 minutes ago Author Posted 21 minutes ago 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
Recommended Posts
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 accountSign in
Already have an account? Sign in here.
Sign In Now