considerations on debug information

[jpiesing]

I'm trying to interpret the debug information in the .json version of the report and it's not obvious. Here's the example.

            "[2025-10-08T14:10:11.975Z][DBG] fetching segment http://dpctf.duckdns.org:8000/content/cfhd_sets/12.5_25_50/t34/2023-09-01/1/76800.m4s  ",
            "[2025-10-08T14:10:12.078Z][DBG] appending buffer, size: 85249  ",
            "[2025-10-08T14:10:12.093Z][DBG] source buffer updated, buffered ranges: [{\"start\":0,\"end\":8}]  ",
            "[2025-10-08T14:10:12.093Z][DBG] reached maximum buffer time, stop buffering  ",
            "[2025-10-08T14:10:14.004Z][DBG] buffering segment 4  ",

What is going on here? It stops buffering at 14:10:12.093 and then starts buffering just under 2s later at 14:10:14.004? What causes it to re-start buffering? It might help to have an additional debug statement in the event handler (or whatever) that causes this buffering to resume?

            "[2025-10-08T14:10:14.005Z][DBG] fetching segment http://dpctf.duckdns.org:8000/content/cfhd_sets/12.5_25_50/t32/2023-09-01/1/102400.m4s  ",
            "[2025-10-08T14:10:14.109Z][DBG] fetching segment http://dpctf.duckdns.org:8000/content/cfhd_sets/12.5_25_50/t32/2023-09-01/1/init.mp4  ",

There is no debug message when the data has been retrieved. Is this correct? Does that mean we cannot tell how long the above took to arrive? It might help to add a debug message around the highlighted line?

IMHO one key question is what is going on between 14:10:14.109Z and 14:10:18.194Z? Is segment 4 delayed in arriving or has it arrived and it's just not being processed because the trigger to process it isn't being acted upon?

            "[2025-10-08T14:10:18.194Z][INF] video is waiting  ",
            "[2025-10-08T14:10:19.426Z][DBG] appending buffer, size: 960  ",

Presumably this is the init.mp4 that was fetched at 14:10.14.109, i.e. 5s earlier? Why does it wait so long before appending it? Does the lack of a debug message when data is retrieved mean we can't tell if it's waiting for the data to arrive or if it's waiting for something else?

            "[2025-10-08T14:10:19.427Z][DBG] source buffer updated, buffered ranges: [{\"start\":0,\"end\":8}]  ",
            "[2025-10-08T14:10:19.427Z][DBG] appending buffer, size: 124524  ",
            "[2025-10-08T14:10:19.429Z][DBG] source buffer updated, buffered ranges: [{\"start\":0,\"end\":10}]  ",
            "[2025-10-08T14:10:19.429Z][DBG] buffering segment 5  ",
            "[2025-10-08T14:10:19.430Z][DBG] fetching segment http://dpctf.duckdns.org:8000/content/cfhd_sets/12.5_25_50/t32/2023-09-01/1/128000.m4s  ",
            "[2025-10-08T14:10:19.444Z][INF] video can play  ",
            "[2025-10-08T14:10:19.447Z][INF] video is playing  ",
            "[2025-10-08T14:10:19.470Z][DBG] appending buffer, size: 119499  ",
            "[2025-10-08T14:10:19.584Z][DBG] source buffer updated, buffered ranges: [{\"start\":0,\"end\":12}]  ",
            "[2025-10-08T14:10:19.585Z][DBG] buffering segment 6  ",

It begins to feel to me like there's a really subtle race condition in player.js, IMHO that's more likely than the server blocking delivering the data for 5s.

[louaybassbouss]

What is going on here? It stops buffering at 14:10:12.093 and then starts buffering just under 2s later at 14:10:14.004? What causes it to re-start buffering?

After playing 2s (from 14:10:12 to 14:10:14) the player buffers a new segment to keep the buffer above the min-buffer-duration

There is no debug message when the data has been retrieved. Is this correct? Does that mean we cannot tell how long the above took to arrive?

When the data arrives, it will appended to the buffer. So you can use the timestamps when Segment is requested and when it is appended to the buffer to calculate the time needed to fetch the data. Exception on representation switching the init segment must be appended before. But in general yes, it makes sense to have a dedicated message when the data arrives.

IMHO one key question is what is going on between 14:10:14.109Z and 14:10:18.194Z? Is segment 4 delayed in arriving or has it arrived and it's just not being processed because the trigger to process it isn't being acted upon?

As you can see in the logs, fetching video segment triggers also fetching init segment because there was representation switching. The new segment must be appended to the buffer after appending the init segment. There is a logic in the player to handle this order, but in any case both segments must be arrived in order to proceed (@FritzHeiden feel free to provide details on this). Again here, the same debug message when segments arrive will make this clear.

It begins to feel to me like there's a really subtle race condition in player.js, IMHO that's more likely than the server blocking delivering the data for 5s.

@FritzHeiden please add the new debug message when segments arrive and let us do further investigation

[jpiesing]

I would also recommend debug statements around the following;

• the startBuffering method
• the bufferVideo method covering each path through the method - if there is a race condition somewhere, this method returning earlier than expected may well be it
• anywhere else the variable _maxBufferSizeReached is touched