possible missed documents with ebuttd encoder

[kozmaz87]

The following is possible:

(env) C:\Coding\ebu-tt-live-toolkit>ebu-ebuttd-encoder -i 5
[INFO] (2016-09-26 09:22:55,173) in ebu_simple_consumer[54] - This is the EBU-TT-D encoder
[INFO] (2016-09-26 09:22:55,206) in twisted[154] - Starting factory <ebu_tt_live.twisted.websocket.BroadcastClientFactory object at 0x000000000596C978>
[INFO] (2016-09-26 09:22:56,782) in ebu_tt_live.node.consumer[28] - Creating document sequence from first document <ebu_tt_live.documents.ebutt3.EBUTT3Document object at 0x00000000059CB860>
[INFO] (2016-09-26 09:22:56,782) in document_logger[39] - Document TestSequence1__567 received. Calculated activation: [9:22:57.661000; 9:22:58.661000]
[INFO] (2016-09-26 09:22:56,783) in document_logger[673] - TestSequence1: requesting segment (9:22:55.174000 - 9:23:00.174000)
[INFO] (2016-09-26 09:22:56,783) in document_logger[374] - TestSequence1__567: requesting segment (9:22:55.174000 - 9:22:58.661000)
[INFO] (2016-09-26 09:22:58,743) in document_logger[39] - Document TestSequence1__568 received. Calculated activation: [9:22:59.661000; 9:23:00.661000]
[INFO] (2016-09-26 09:23:00,744) in document_logger[39] - Document TestSequence1__569 received. Calculated activation: [9:23:01.661000; 9:23:02.661000]
[INFO] (2016-09-26 09:23:01,782) in document_logger[673] - TestSequence1: requesting segment (9:23:00.174000 - 9:23:05.174000)
[INFO] (2016-09-26 09:23:01,785) in document_logger[374] - TestSequence1__568: requesting segment (9:23:00.174000 - 9:23:00.661000)
[INFO] (2016-09-26 09:23:01,825) in document_logger[374] - TestSequence1__569: requesting segment (9:23:00.661000 - 9:23:02.661000)
[INFO] (2016-09-26 09:23:02,733) in document_logger[39] - Document TestSequence1__570 received. Calculated activation: [9:23:03.661000; 9:23:04.661000]
[INFO] (2016-09-26 09:23:04,713) in document_logger[39] - Document TestSequence1__571 received. Calculated activation: [9:23:05.660000; 9:23:06.660000]
[INFO] (2016-09-26 09:23:06,743) in document_logger[39] - Document TestSequence1__572 received. Calculated activation: [9:23:07.660000; 9:23:08.660000]
[INFO] (2016-09-26 09:23:06,782) in document_logger[673] - TestSequence1: requesting segment (9:23:05.174000 - 9:23:10.174000)
[INFO] (2016-09-26 09:23:06,783) in document_logger[374] - TestSequence1__571: requesting segment (9:23:05.174000 - 9:23:06.660000)
[INFO] (2016-09-26 09:23:06,812) in document_logger[374] - TestSequence1__572: requesting segment (9:23:06.660000 - 9:23:08.660000)
[INFO] (2016-09-26 09:23:08,736) in document_logger[39] - Document TestSequence1__573 received. Calculated activation: [9:23:09.660000; 9:23:10.660000]
[INFO] (2016-09-26 09:23:10,237) in twisted[154] - Received SIGINT, shutting down.
[INFO] (2016-09-26 09:23:10,239) in twisted[154] - Stopping factory <ebu_tt_live.twisted.websocket.BroadcastClientFactory object at 0x000000000596C978>
[INFO] (2016-09-26 09:23:10,239) in twisted[154] - Main loop terminated.

In the above example document 570 never gets into the encoder because it is missing its place.

[nigelmegitt]

Is this a duplicate of #269 ?

[nigelmegitt]

There are two things going on here. Firstly the request for the segment that 570 occupies comes before it is available, so it is completely reasonable not to output it, though we should avoid configuring scenarios in which that can happen.

Secondly the segment period is requested around 1.5s after it has begun but around 3.5s before it has ended. This means that on output, the availability time of the output will be at least 1.5s after it has begun, plus the time it took to compute and save that segment, and that the latter 3.5s worth of subtitle text will be missing. So if there is a packager looking for that segment assuming that it is available at its begin time then it will fail. And if there is one looking for it at its end time then it will succeed and get incomplete content.

If there is a bug here it is that there is no warning on requests for a segment before that segment has ended, and possibly that the segment request scheduling is mistimed - the first request comes in around 0.001s after the document sequence is created, when the sequence interval is 5s - the first request should be made at the document sequence creation time + the interval, at the earliest, to ensure that any content destined for the segment has actually arrived.

This bug was filed some time ago - I'm not sure if this behaviour has now been fixed - @kozmaz87 do you know?

One (obvious) operational consequences from this too:

• we have to leave some time for the encoder to do its job before expecting the encoded output to be available, and this adds to the overall latency of the system.