[Stream] STREAM_NOTIFY_PROGRESS over HTTP emitted irregularly for last chunk of data #10031

Description

Problem

Files

file echo.php

<?php

$fsize = 1000;
$chunksize = 99;
$chunks = floor($fsize / $chunksize); // 10 chunks * 99 bytes
$lastchunksize = $fsize - $chunksize * $chunks; // 1 chunk * 10 bytes

header("Content-length: " . $fsize);
flush();
for ($chunk = 1; $chunk <= $chunks; $chunk++) {
    echo str_repeat('x', $chunksize);
    @ob_flush();
    usleep(50 * 1000);
}

echo str_repeat('x', $lastchunksize);

file test.php

<?php

$context = stream_context_create(['http' => ['ignore_errors' => true,]]);
$lastBytesTransferred = 0;
stream_context_set_params($context, ['notification' => function ($code, $s, $m, $mc, $bytes_transferred, $bytes_max)
use (&$lastBytesTransferred) {
    $progress = $bytes_max ? $bytes_transferred / $bytes_max * 100 : 0;
    $chunksize = $bytes_transferred - $lastBytesTransferred;
    if ($code === STREAM_NOTIFY_PROGRESS) echo "\nprogress: $progress% ($bytes_transferred/$bytes_max b) (chunksize=$chunksize)";
    if ($code === STREAM_NOTIFY_FILE_SIZE_IS) echo "\nexpected filesize= $bytes_max";
    if ($code === STREAM_NOTIFY_COMPLETED) echo "\nSTREAM_NOTIFY_COMPLETED";
    $lastBytesTransferred = $bytes_transferred;
    @ob_flush();
}]);

$get = file_get_contents('http://localhost:8000/echo.php', false, $context);

if (!$get) die("\nERROR during file_get_contents. is the local server running? ( php -\"dxdebug.mode\"=off -S localhost:8000 )\n");

echo "\ngot filesize=" . strlen($get) . PHP_EOL;

CLI commands:

# to start local server
php -S localhost:8000
# to run the test
php test.php

Wrong output (happens irregularly):

> php .\src\test.php

expected filesize= 1000
progress: 0% (0/1000 b) (chunksize=0)
progress: 9.9% (99/1000 b) (chunksize=99)
progress: 19.8% (198/1000 b) (chunksize=99)
progress: 29.7% (297/1000 b) (chunksize=99)
progress: 39.6% (396/1000 b) (chunksize=99)
progress: 49.5% (495/1000 b) (chunksize=99)
progress: 59.4% (594/1000 b) (chunksize=99)
progress: 69.3% (693/1000 b) (chunksize=99)
progress: 79.2% (792/1000 b) (chunksize=99)
progress: 89.1% (891/1000 b) (chunksize=99)
progress: 90.1% (901/1000 b) (chunksize=10)
got filesize=1000

Correct output:

> php .\src\test.php

expected filesize= 1000
progress: 0% (0/1000 b) (chunksize=0)
progress: 9.9% (99/1000 b) (chunksize=99)
progress: 19.8% (198/1000 b) (chunksize=99)
progress: 29.7% (297/1000 b) (chunksize=99)
progress: 39.6% (396/1000 b) (chunksize=99)
progress: 49.5% (495/1000 b) (chunksize=99)
progress: 59.4% (594/1000 b) (chunksize=99)
progress: 69.3% (693/1000 b) (chunksize=99)
progress: 79.2% (792/1000 b) (chunksize=99)
progress: 89.1% (891/1000 b) (chunksize=99)
progress: 99% (990/1000 b) (chunksize=99)
progress: 100% (1000/1000 b) (chunksize=10)
got filesize=1000

Description

The file echo.php generates a series of 1000 consecutive "x"s. The data is emitted with intervals of 50ms (usleep(50 * 1000)), in 10 chunks sized 99bytes, plus one final chunk of 10bytes (99*10 + 10 = 1000).

The script test.php fetches the data from the url /echo.php of the local web server. file_get_contents is passed a context with a notification callback. This callback prints the download progress: percentage, bytes transferred, total bytes, current chunk size. The chunk size is calculated by subtracting the previous $bytes_transferred from the current $bytes_transferred.

If you run php test.php multiple times, you will see that sometimes the event last 1/2 STREAM_NOTIFY_PROGRESS events are not emitted correctly.

The last events should always be:

• progress: 89.1% (891/1000 b) (chunksize=99) = chunk 9
• progress: 99% (**990**/1000 b) (chunksize=**99**) = chunk 10
• progress: 100% (**1000**/1000 b) (chunksize=**10**) = chunk 11

Instead, sometimes the last chunks are messed up:

• progress: 89.1% (891/1000 b) (chunksize=99) = chunk 9
• progress: 90.1% (**901**/1000 b) (chunksize=**10**) = chunk 10. This line here is the culprit. This chunk has the correct size of the last chunk (10 bytes), but it's reported as being the 10th! In reality, the 10th chunk is still 99bytes large, and the 11th is the 10bytes one.

When this problem occurs, 100% progress is never emitted (as the 10th chunk is mistaken for the 11th).

I don't think this is a problem in the communication between php and the web server. Any possible delay in the communication shouldn't interfere with how the chunks are passed to the notification callback. I tried running curl -#O multiple times to see how curl receives the data. This is the command line i used (powershell): 1..10 | % { curl -#LO http://localhost:8000/echo.php *>&1 | php -r "preg_match_all('/[0-9\.]+/m', stream_get_contents(STDIN), `$m);echo implode(', ', `$m[0]).PHP_EOL;" ;}. For each iteration (1..10), this prints every progress percentage reported by curl.

It prints something like this:

19.8, 39.6, 49.5, 59.4, 69.3, 79.2, 99.0, 100.0
19.8, 29.7, 39.6, 49.5, 59.4, 69.3, 79.2, 89.1, 99.0, 100.0
19.8, 29.7, 39.6, 49.5, 59.4, 69.3, 89.1, 99.0, 100.0
19.8, 39.6, 49.5, 59.4, 69.3, 79.2, 89.1, 99.0, 100.0
19.8, 29.7, 39.6, 49.5, 59.4, 69.3, 79.2, 99.0, 100.0
19.8, 29.7, 39.6, 59.4, 69.3, 79.2, 89.1, 99.0, 100.0
19.8, 29.7, 39.6, 49.5, 59.4, 79.2, 89.1, 99.0, 100.0
19.8, 29.7, 39.6, 49.5, 59.4, 69.3, 79.2, 89.1, 99.0, 100.0
19.8, 39.6, 49.5, 59.4, 69.3, 79.2, 89.1, 99.0, 100.0
19.8, 29.7, 39.6, 49.5, 59.4, 69.3, 79.2, 89.1, 99.0, 100.0

As you can see, curl doesn't always report its progress, but even though it skips some reporting, it always has the correct progress percentages. It always ends with 89.1, 99.0, 100.0, which is the correct sequence.

php on the other hand sometimes ends with 89.1, 90.1.

In conclusion, at the moment the STREAM_NOTIFY_PROGRESS event is not reliable.

I cannot determine why this problem occures only sometimes. I really can't. This appears extremely frequently when the chunks are transferred with varying sizes (eg if the php script on the server calls readfile(), and/or if the connection to the server is not stable).

PHP Version

PHP 8.1.12

Operating System

Windows 11 (10.0.22621.819)