stream_copy_to_stream returns false when data copied is less than $maxlength

[stevesutton-hds]

Description

The following code:

<?php
$streaminput = popen("my_command", "r");  // Some command which has generated output that sometimes has less than the 10000 read size bytes of data (if you care, I was actually calling postgres's pg_dump)
$streamoutput = popen("another_command", "w"); // I was actually using input pipe (i.e. stdin) of command started with proc_open() here (actually it was gzip, and I used proc_open so that I could read stdout here too), but AFAIK, that's just a stream to stdin as is the case in this example)
stream_set_blocking($streamoutput, false);

$expectedPos = 0;
while (!feof($streaminput)) {
  $copied = stream_copy_to_stream($streaminput, $streamoutput, 10000);
  $expectedPos += $copied;

  // if ($copied === false) { echo "\nCopied is false!";
  // if ($copied === 0) { echo "\nCopied is 0!"; // This message never printed

  if ($copied == 0) {  // Note: I later discovered that the unexpected false return caused the branch to execute because of == instead of ===, even though the stream position had advanced.
   echo ".";
   sleep 1;
   continue;
  else {
    echo "\nCopied $copied, Expected position $expectedPos, actual position " . ftell($streaminput);
  }

}

Resulted in this output:

Copied 10000, Expected position 10000, actual position 10000
Copied 10000, Expected position 20000, actual position 20000
Copied 10000, Expected position 30000, actual position 30000.
Copied 10000, Expected position 40000, actual position 48192
Copied 10000, Expected position 50000, actual position 58192

But I expected this output instead:

Copied 10000, Expected position 10000, actual position 10000
Copied 10000, Expected position 20000, actual position 20000
Copied 10000, Expected position 30000, actual position 30000
Copied 8192, Expected position 38192, actual position 38192
Copied 10000, Expected position 48192, actual position 48192

Notice how, in the real output, when the dot appears after 30000 (suggesting 0 bytes were copied, in fact 8192 bytes appear to have been copied according to the position returned by ftell()) - you can confirm $copied is false by uncommenting the relevant lines.

Each time I got a "." in the output I observed that the actual stream position had advanced, but always by less than the 10000 .... if it advanced by 10000, the value of $copied was 10000 and I got the full message. (edit: I've confirmed this by printing ftell($inputstream) with the "." in my local code, but I've not updated the example code/output above)

Also note that $streaminput never got to an eof state, and appeared most time to have simply stopped adding to the stream, and I end up killing the php script with ^C

PHP Version

PHP 8.1.2-1ubuntu2.13 (cli) (built: Jun 28 2023 14:01:49) (NTS)

Operating System

Ubuntu 22.04.2 LTS \n \l (running on WSL in Windows 11)

[stevesutton-hds]

So to be clear, it seems that stream_copy_to_stream() returns false, when fewer than the requested number of bytes were copied .... I would expect it to return the actual number of bytes copied, but it only actually did this when the requested number of bytes were copied.

[damianwadley]

Are you really on PHP 8.1.2? Not, say, 8.1.21? I don't remember where but there was a bug or two about the magic 8192 that has been fixed...

[stevesutton-hds]

I copied that version direct from php --version. I have been googling this for several hours + searched this project in github for stream_copy_to_stream() with no success.

Seems to be the latest version for my distro, I've just done apt update and apt install php and it's the same version

[damianwadley]

This sounds familiar so I feel like it's been fixed at some point... but I haven't been able to reproduce it with 8.1.2 myself using a variety of fuzzed input streams so I'm not sure.

[stevesutton-hds]

Ahh, just realised I missed something. I turned blocking off on the 2nd pipe, as otherwise the stream_copy_to_stream just hung when it was less than 10000 bytes to copy. I've edited the example - see I've added the stream_set_blocking() call.

Also, try this for a more exact reproduction of the $outputstream:

        $gzipdescriptorspec = array(
          0 => array("pipe", "r"),  // stdin
          1 => array("pipe", "w"),  // stdout -> we use this
          2 => array("pipe", "w")   // stderr 
        );

        echo "Starting gzip\n";

        $gzip_process = proc_open('gzip', $gzipdescriptorspec, $gzippipes);

// Replace the $outputstream with $gzippipes[0] in the above example code

[stevesutton-hds]

Note, with blocking left on, the code runs as expected (value of $copied is 10000 every time) until some point when it just freezes/blocks at the stream_copy_to_stream() call, presumably because of <10000 input ..... I turned the blocking off on the destination (gzip) stream to get around this, which is when it started to happen.

edit: Note this blocking only occurs when I specify $maxlength ..... if I copy the stream just specifing the in and out streams, the copy completes in full, successfully (Although just to be completely precise, when I was doing it this way, gzip wasn't the destination, it was just a stream to S3)

[damianwadley]

Needing to set it as non-blocking would make sense.

I think I can reproduce this using recent PHP: somewhat randomly (I'm still fuzzing the input and output streams), the copy returns 0/false as if it didn't copy but ftell indicates that the stream had moved down. Additionally, ftelling on both streams shows them out of sync, where the input stream advances normally but the output stream is somewhere in between the expected position and the actual (input) position.

Some of this makes sense. By setting the output stream as non-blocking, a writer has to take responsibility for making sure everything gets written as desired. So I'm thinking maybe stream_copy_to_stream isn't doing that: it reads some amount <=10000 bytes, but when it's unable to write everything it gives up and thus puts the two streams out of sync.

That should be simple to confirm on your end: when the bug happens in the middle of a copy, do you see the output source (ie. the gunzipped file) missing some chunks of input?

However, what else can stream_copy_to_stream do? If you set the output as nonblocking and it's able to read but not write, the only sensible thing would be to retry... which is effectively the same as keeping the output stream as blocking.

So I'm not sure if there is something inside PHP that needs to be fixed here. The output stream should be blocking, logically, and if anything it's the input stream that doesn't need to be. But there shouldn't be much of a need for the latter as the stream will close when there's no more output... unless the process is still running?

If that's right then you should not turn off blocking on $streamoutput and instead focus on why $streaminput doesn't seem to be ending. (Be sure to give it a couple minutes of waiting, just to be sure that it really is stuck and is not just taking an unexpectedly long time.)

Additionally, insert obligatory comment here on the questionable necessity of using a PHP script to pipe output between two processes.

[stevesutton-hds]

Well, I've not looked at the output properly yet, and it's getting late tonight.

The main point stands, however, that if the stream copy does indeed copy bytes, I would expect it to return the actual number of bytes copied .... even if less than the maximum.

Additionally, insert obligatory comment here on the questionable necessity of using a PHP script to pipe output between two processes.

It's a background process kicked off from a web front end (because it could take a while). I'm trying to write something to display progress, by counting the number of bytes output by the first process. I'm intercepting between the export and the gzip because I can predict the total bytes output so I can give a completed / total figure whereas I can't predict the final gzipped size, so monitoring the final output of that is useless to indicate progress.

[stevesutton-hds]

Oh, wait, I think I missed your point. You are suggesting that perhaps the read succeeds, but the write fails.

I was assuming that the write would just buffer without ever blocking or failing ..... but yes, maybe if the write fails entirely, that would explain what is happening here.

I'd be a little surprised if that is what is actually happening as there's nothing consistent about the timing of the write failing in terms of time or data, PLUS, subsequent calls to the copy do succeed, so it doesn't make much sense for the destination process to have failed entirely .... but yes, perhaps a transient write error is worth me looking into further. Thanks!

PS. Worth mentioning that the doesn't seem to be a way to get further information on the nature of the error (if that's what it really is) when false is returned ..... that would be a help if that could be added, as it may just be lack of information that's misleading me about what is happening here.

[stevesutton-hds]

Looking into this further, it seems as though it might be related to the bugs mentioned at https://www.php.net/manual/en/function.stream-set-blocking.php#110997 (the 3rd one mentions proc_open() and blocking) Note that although I'm running ubuntu linux, this is running in WSL on Windows 11, and so whatever underlying issues in windows cause problems may be causing the same thing for me.

[bukka]

I have just done few checking in the code and think I have got a good idea what happened here.

For the reference the code implementing the copying for pipes and other network streams can be seen here:

php-src/main/streams/streams.c

Lines 1742 to 1775 in bb1109d

	while(1) {
	size_t readchunk = sizeof(buf);
	ssize_t didread;
	char *writeptr;
	if (maxlen && (maxlen - haveread) < readchunk) {
	readchunk = maxlen - haveread;
	}
	didread = php_stream_read(src, buf, readchunk);
	if (didread <= 0) {
	*len = haveread;
	return didread < 0 ? FAILURE : SUCCESS;
	}
	towrite = didread;
	writeptr = buf;
	haveread += didread;
	while (towrite) {
	ssize_t didwrite = php_stream_write(dest, writeptr, towrite);
	if (didwrite <= 0) {
	*len = haveread - (didread - towrite);
	return FAILURE;
	}
	towrite -= didwrite;
	writeptr += didwrite;
	}
	if (maxlen && maxlen == haveread) {
	break;
	}
	}

The fact that output was set to non blocking means that write can fail if the write side is not ready and that's exactly what happened here. Specifically php_stream_write is not able to write anything so FAILURE is returned. The reason why it needs to fail is that some data read into buffer buf will get lost as there is currently no way how to resume operation with the read data. Returning false is logical and correct in this case. In terms of position, this failed call moved position by 8192 bytes because that's what the read chunk size is. Some of this data is lost. The next copy is successful so the position moves by 10000.

I think we could potentially look into improving the non blocking streams copy handling. We would need to somehow buffer the read data and somehow let user know which operation is awaited. This actually reminds me the PR discussion that we had for SSL layer that needs something similar so it might make sense to look to some generic API for this. In this case it would just ability to check if the read site wants read and write side wants write but would be probably good to have some generic op for this. In terms of buffer we could consider using write buffer or introduce a new buffer if it the write buffer is not convenient / safe to use in this scenario.

I will change this to feature request as I don't see any bug here.