Problem/Motivation

This issue is a follow-up to #3285230: Migrate's DownloadFunctionalTest:: testExceptionThrow() is failing on guzzlehttp/psr7 2.3.0.

The download process plugin in the migrate module uses Guzzle to copy a file from source to destination. When this is done in DownloadFunctionalTest::testExceptionThrow(), the testing system tries to save the HTTP request in case it is needed for debugging. For some reason, BrowserHtmlDebugTrait::getResponseLogHandler() tries to convert the destination stream, not the source stream, to a string. In #3285230, we handled that by testing isReadable() before casting the stream to a string.

For this issue, let's figure out why the testing system is trying to save the result of the destination stream instead of the source stream.

We should also figure out why some of us found that DownloadFunctionalTest::testExceptionThrow() passed locally but others got the same failure as the testbot.

Steps to reproduce

  1. Run DownloadFunctionalTest.
  2. Review the "HTML output was generated".

For example, using the current 10.0.x:

$ vendor/bin/phpunit -c core core/modules/migrate/tests/src/Functional/process/DownloadFunctionalTest.php
PHPUnit 9.5.20 #StandWithUkraine

Testing Drupal\Tests\migrate\Functional\process\DownloadFunctionalTest
.                                                                   1 / 1 (100%)

Time: 00:01.972, Memory: 6.00 MB

OK (1 test, 11 assertions)

HTML output was generated
https://drupal.ddev.site/sites/simpletest/browser_output/Drupal_Tests_migrate_Functional_process_DownloadFunctionalTest-17-79589012.html
https://drupal.ddev.site/sites/simpletest/browser_output/Drupal_Tests_migrate_Functional_process_DownloadFunctionalTest-18-79589012.html

Opening the second link in a browser, I see this:

ID #18 (Previous | Next)
---
Called from GuzzleHttp\Promise\FulfilledPromise::GuzzleHttp\Promise\{closure}() line 41
---
GET request to: http://web/core/misc/favicon.ico
---
Response is not readable.
---

The last line comes from the test we added in #3285230: it means that the stream $response->getBody() represents the destination of the download process, so it is not readable. The source stream is http://web/core/misc/favicon.ico, which is readable.

Proposed resolution

  1. Add a code comment explaining why the test for isReadable() is needed.

Remaining tasks

According to the API docs for Psr\Http\Message\StreamInterface::__toString,

This method MUST NOT raise an exception in order to conform with PHP's string casting operations.

User interface changes

None

API changes

None

Data model changes

None

Release notes snippet

N/A

Issue fork drupal-3292980

Command icon Show commands

Start within a Git clone of the project using the version control instructions.

Or, if you do not have SSH keys set up on git.drupalcode.org:

Comments

benjifisher created an issue. See original summary.

benjifisher’s picture

benjifisher’s picture

Issue summary: View changes

I repeated the test in the issue summary with Drupal 9.4.1:

$ vendor/bin/phpunit -c core core/modules/migrate/tests/src/Functional/process/DownloadFunctionalTest.php
PHPUnit 8.5.26 #StandWithUkraine

Testing Drupal\Tests\migrate\Functional\process\DownloadFunctionalTest
.                                                                   1 / 1 (100%)

Time: 2.04 seconds, Memory: 4.00 MB

OK (1 test, 10 assertions)

HTML output was generated
https://drupal.ddev.site/sites/simpletest/browser_output/Drupal_Tests_migrate_Functional_process_DownloadFunctionalTest-19-15906678.html
https://drupal.ddev.site/sites/simpletest/browser_output/Drupal_Tests_migrate_Functional_process_DownloadFunctionalTest-20-15906678.html

This time, when I open the second link in a browser, I see this:

ID #20 (Previous | Next)
---
Called from GuzzleHttp\Promise\FulfilledPromise::GuzzleHttp\Promise\{closure}() line 41
---
GET request to: http://web/core/misc/favicon.ico
---
---

I think that just means that the stream is still unreadable, but the older version of guzzlehttp/psr7 casts it to an empty string. Before #3285230: Migrate's DownloadFunctionalTest:: testExceptionThrow() is failing on guzzlehttp/psr7 2.3.0, we used @(string) $response->getBody() to cast to a string and suppress errors. (Does that suppress errors but not exceptions?)

benjifisher’s picture

According to @mikelutz on Slack:

... we pass a full stream to the sink option for guzzle and not a stream string to make guzzle create it’s own stream for output. ... the way we wire guzzle up in the download plugin, I don’t think there really is such a thing as a ‘source stream’. I think guzzle pumps and drains that source stream into the destination stream right as the response comes in, before it even starts parsing headers or anything. All that’s left IS the destination stream, and that’s probably exactly how it’s supposed to work when you use the sink option with a stream.

Here is the code from the download plugin:

    $destination_stream = @fopen($final_destination, 'w');
    // ...

    // Stream the request body directly to the final destination stream.
    $this->configuration['guzzle_options']['sink'] = $destination_stream;

    try {
      // Make the request. Guzzle throws an exception for anything but 200.
      $this->httpClient->get($source, $this->configuration['guzzle_options']);
    }
    catch (\Exception $e) {
      throw new MigrateException("{$e->getMessage()} ($source)");
    }

The next few lines may also be relevant here:

    if (is_resource($destination_stream)) {
      fclose($destination_stream);
    }

    return $final_destination;

Why do we close the stream and then return it? Is that related to the "HTML output was generated"?

Edit: We return the string $final_destination, not the closed stream, so there is nothing wrong with these lines.

benjifisher’s picture

If the quoted explanation in #4 is correct, then the resolution to this issue might be simply to add a code comment. Something like this:

              $stream = $response->getBody();

              // Get the response body as a string. If the request is sent with
              // $options['sink'] = $sink, then $stream is set to $sink, which
              // may not be readable.
              $body = $stream->isReadable()
                ? (string) $stream
                : 'Response is not readable.';

Is that accurate? Can we get a link to the Guzzle docs supporting this?

benjifisher’s picture

Status: Active » Needs review

I cannot find any documentation for how the 'sink' option affects the response, so I am adding a test to confirm the comment.

MR 2469 adds the test and a comment similar to the one in #5.

I am giving @mikelutz credit for the helpful discussion on Slack. See #4.

Is Drupal\Tests\Core\Http a good namespace for the new test?

benjifisher’s picture

Issue summary: View changes
benjifisher’s picture

Issue summary: View changes
mikelutz’s picture

Status: Needs review » Needs work

The code comment is fine, the test you added probably should not get committed.

You are just testing guzzle. I mean you could try to make an argument that you are testing \Drupal::httpClient() but all that does is return the http_client service from the container and the http_client service is GuzzleHttp\Client, so there is nothing there to really test.

mikelutz’s picture

I got tired of guessing, so I decided to finally look it up.

/**
 * sink: (resource|string|StreamInterface) Where the data of the
 * response is written to. Defaults to a PHP temp stream. Providing a
 * string will write data to a file by the given name.
 */
const SINK = 'sink';

It always dumps the download into a stream and returns that when you call getBody(). By default that stream is php://temp which is opened r+. The download is drained into the sink, the sink seek index is reset to 0 and that’s always what you get back. We are overriding that php://temp with a file stream that we opened 'w' instead of 'r+'.

The only way to get the actual download stream is to set

/**
 * stream: Set to true to attempt to stream a response rather than
 * download it all up-front.
 */
const STREAM = 'stream';

IF we opened the file 'r+' instead of 'w'.. then the response would act the same, and we probably wouldn't have noticed any difference in the behavior of $response->getBody().

list($stream, $headers) = $this->checkDecode($options, $headers, $stream);
$stream = Psr7\stream_for($stream);
$sink = $stream;

if (strcasecmp('HEAD', $request->getMethod())) {
    $sink = $this->createSink($stream, $options);
}

$response = new Psr7\Response($status, $headers, $sink, $ver, $reason);

if (isset($options['on_headers'])) {
    try {
        $options['on_headers']($response);
    } catch (\Exception $e) {
        $msg = 'An error was encountered during the on_headers event';
        $ex = new RequestException($msg, $request, $response, $e);
        return \GuzzleHttp\Promise\rejection_for($ex);
    }
}

// Do not drain when the request is a HEAD request because they have
// no body.
if ($sink !== $stream) {
    $this->drain(
        $stream,
        $sink,
        $response->getHeaderLine('Content-Length')
    );
}

There’s the meat from StreamHandler::createResponse(), but the good stuff is in createSink()

private function createSink(StreamInterface $stream, array $options)
{
    if (!empty($options['stream'])) {
        return $stream;
    }

    $sink = isset($options['sink'])
        ? $options['sink']
        : fopen('php://temp', 'r+');

    return is_string($sink)
        ? new Psr7\LazyOpenStream($sink, 'w+')
        : Psr7\stream_for($sink);
}

It opens a stream and drains the download into it and sets that as the response body either way. It’s not unreadable because we set a `sink`, it’s unreadable because we overrode the read/write sink guzzle would have used with something that we opened write-only.

I do really feel that the documentation in the ‘sink’ and ‘stream’ options sufficiently describes what’s happening here.

benjifisher’s picture

Title: Testing system tries to save the wrong stream when using Guzzle » Testing system should explain why Guzzle responses can be unreadable
Status: Needs work » Needs review

@mikelutz:

Thanks for the review.

If anyone else is interested, @mikelutz and I discussed this issue at length during the #3294422: [meeting] Migrate Meeting 2022-07-07 2100Z.

I updated the MR, removing the test and changing the comment to this:

              // Get the response body as a string. The response stream is set
              // to the sink, which defaults to a readable temp stream but can
              // be overridden by setting $options['sink'].

Part of our discussion is that Guzzle is not doing anything wrong, and our comment should not suggest that it is. In that spirit, I am updating the issue title.

quietone’s picture

Issue summary: View changes
Status: Needs review » Reviewed & tested by the community
Issue tags: +Bug Smash Initiative

I read the discussion in Slack today between @benjifisher and @mikelutz and agree with the analysis and conclusion.

This comment is definitely and improvement and is helpful.

Based on the discussion I am removing the second item, adding a test, from the proposed resolution section of the Issue Summary. While helpful for understanding this mikelutz points out that it is testing Guzzle not Drupal.

Now, setting to RTBC.

larowlan’s picture

Saving issue credit. Crediting @mikelutz and @quietone for discussion here and on slack that went into resolving this issue.

larowlan’s picture

Version: 9.5.x-dev » 9.4.x-dev
Status: Reviewed & tested by the community » Fixed

Committed to 10.1.x and backported all the way to 9.4.x for branch consistency as there's little risk of disruption here.

  • larowlan committed 26dfb36 on 10.0.x
    Issue #3292980 by benjifisher, mikelutz, quietone: Testing system should...
  • larowlan committed 6b1c5e3 on 10.1.x
    Issue #3292980 by benjifisher, mikelutz, quietone: Testing system should...
  • larowlan committed 100a340 on 9.4.x
    Issue #3292980 by benjifisher, mikelutz, quietone: Testing system should...
  • larowlan committed 0b3eb21 on 9.5.x
    Issue #3292980 by benjifisher, mikelutz, quietone: Testing system should...

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.