Problem/Motivation

EntityResourceTestBase tests fail randomly. See https://www.drupal.org/pift-ci-job/564977. I think this has only been seen on PHP7.

Proposed resolution

Remaining tasks

User interface changes

API changes

Data model changes

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

alexpott created an issue. See original summary.

alexpott’s picture

One thing I've noticed that has changed is that we're seeing

HTML output was generated
http://localhost/checkout/sites/simpletest/browser_output/Drupal_Tests_hal_Functional_EntityResource_Block_BlockHalJsonCookieTest-1-85940352.html

in the logs. This will be because the browser is run by root and can write anywhere so now it's doing browser output for functional php unit tests and just dumping the stuff in the root. oh boy.

Wim Leers’s picture

This is probably related to #2832853: Random fail in hal EntityTestHalJsonAnonTest::testPost via rest EntityResourceTestBase::testPost. I closed that because I hadn't seen it happen in more than two weeks. EDIT: but that was on PHP 5.5, so perhaps not.

alexpott’s picture

On a local CI I can get the fail all the time. Adding some var_dumps() to:

  protected function initAuthentication() {
    // @todo Remove hardcoded use of the 'json' format, and use static::$format
    // + static::$mimeType instead in https://www.drupal.org/node/2820888.
    $user_login_url = Url::fromRoute('user.login.http')
      ->setRouteParameter('_format', 'json');

    $request_body = [
      'name' => $this->account->name->value,
      'pass' => $this->account->passRaw,
    ];

    $request_options[RequestOptions::BODY] = $this->serializer->encode($request_body, 'json');
    $request_options[RequestOptions::HEADERS]['Accept'] = 'application/json';
    var_dump($request_options);
    $response = $this->request('POST', $user_login_url, $request_options);

    var_dump($response);
    var_dump((string)$response->getBody());
    // Parse and store the session cookie.
    $this->sessionCookie = explode(';', $response->getHeader('Set-Cookie')[0], 2)[0];

    // Parse and store the CSRF token and logout token.
    $data = $this->serializer->decode((string)$response->getBody(), static::$format);
    $this->csrfToken = $data['csrf_token'];
    $this->logoutToken = $data['logout_token'];
  }

Output

Request:

array(2) {
      ["body"]=>
      string(39) "{"name":"tHiEojDX","pass":"yqS9hsT5EL"}"
      ["headers"]=>
      array(1) {
        ["Accept"]=>
        string(16) "application/json"
      }
    }

Response

    object(GuzzleHttp\Psr7\Response)#7951 (6) {
      ["reasonPhrase":"GuzzleHttp\Psr7\Response":private]=>
      string(2) "OK"
      ["statusCode":"GuzzleHttp\Psr7\Response":private]=>
      int(200)
      ["headers":"GuzzleHttp\Psr7\Response":private]=>
      array(4) {
        ["Date"]=>
        array(1) {
          [0]=>
          string(29) "Wed, 04 Jan 2017 14:04:27 GMT"
        }
        ["Server"]=>
        array(1) {
          [0]=>
          string(21) "Apache/2.4.7 (Ubuntu)"
        }
        ["Content-Length"]=>
        array(1) {
          [0]=>
          string(3) "493"
        }
        ["Content-Type"]=>
        array(1) {
          [0]=>
          string(29) "text/html; charset=iso-8859-1"
        }
      }
      ["headerNames":"GuzzleHttp\Psr7\Response":private]=>
      array(4) {
        ["date"]=>
        string(4) "Date"
        ["server"]=>
        string(6) "Server"
        ["content-length"]=>
        string(14) "Content-Length"
        ["content-type"]=>
        string(12) "Content-Type"
      }
      ["protocol":"GuzzleHttp\Psr7\Response":private]=>
      string(3) "1.1"
      ["stream":"GuzzleHttp\Psr7\Response":private]=>
      object(GuzzleHttp\Psr7\Stream)#16 (7) {
        ["stream":"GuzzleHttp\Psr7\Stream":private]=>
        resource(6657) of type (stream)
        ["size":"GuzzleHttp\Psr7\Stream":private]=>
        NULL
        ["seekable":"GuzzleHttp\Psr7\Stream":private]=>
        bool(true)
        ["readable":"GuzzleHttp\Psr7\Stream":private]=>
        bool(true)
        ["writable":"GuzzleHttp\Psr7\Stream":private]=>
        bool(true)
        ["uri":"GuzzleHttp\Psr7\Stream":private]=>
        string(10) "php://temp"
        ["customMetadata":"GuzzleHttp\Psr7\Stream":private]=>
        array(0) {
        }
      }
    }

Response body:

    string(493) "

    200 OK

OK
The server encountered an internal error or
misconfiguration and was unable to complete
your request.
Please contact the server administrator at
 [no address given] to inform them of the time this error occurred,
 and the actions you performed just before this error.
More information about this error may be available
in the server error log.

"
alexpott’s picture

So there are two apache error logs here is what is in them:

cat /var/log/apache2/error.log
AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.17.0.5. Set the 'ServerName' directive globally to suppress this message
[Wed Jan 04 14:04:20.134760 2017] [mpm_prefork:notice] [pid 19] AH00163: Apache/2.4.7 (Ubuntu) PHP/7.0.15-dev configured -- resuming normal operations
[Wed Jan 04 14:04:20.134795 2017] [core:notice] [pid 19] AH00094: Command line: '/usr/sbin/apache2 -D FOREGROUND'

And

cat /var/log/apache2/test.apache.error.log
[Wed Jan 04 14:04:27.338512 2017] [:error] [pid 32] [client ::1:55204] Error while attempting to read POST data: 200

The second looks like the error but weird...

Wim Leers’s picture

Eh… wtf. If I search for the string server encountered an internal error or the string unable to complete, I find absolutely nothing. Where is this coming from? :O

Apparently it's an Apache thing: https://duckduckgo.com/?q=%22The+server+encountered+an+internal+error+or...

Can you check your Apache error log?

alexpott’s picture

Looking at how Guzzle sends JSON from the client...

        if (isset($options['json'])) {
            $options['body'] = \GuzzleHttp\json_encode($options['json']);
            unset($options['json']);
            $options['_conditional']['Content-Type'] = 'application/json';
        }

We're missing $options['_conditional']['Content-Type'] = 'application/json';

alexpott’s picture

So this fixes Drupal\Tests\hal\Functional\EntityResource\Block\BlockHalJsonCookieTest and the other tests using the \Drupal\Tests\rest\Functional\CookieResourceTestTrait::initAuthentication().

Now we just have a problem when we send unparseable bodies... these issues are all being caused by a recent addition to PHP7 see https://github.com/php/php-src/commit/9b65a10256e244a6d80027c943b163dd16... and https://github.com/php/php-src/pull/2180

alexpott’s picture

So when I run Drupal\Tests\rest\Functional\EntityResource\User\UserJsonAnonTest I get the same issue being reported in the error log:

cat /var/log/apache2/test.apache.error.log
[Wed Jan 04 16:14:29.078809 2017] [:error] [pid 32] [client ::1:39654] Error while attempting to read POST data: 200

This time the test is doing this:

    $request_options[RequestOptions::HEADERS]['Content-Type'] = static::$mimeType;


    // DX: 400 when no request body.
    $response = $this->request('PATCH', $url, $request_options);
    $this->assertResourceErrorResponse(400, 'No entity content received.', $response);


    $request_options[RequestOptions::BODY] = $unparseable_request_body;


    // DX: 400 when unparseable request body.
    $response = $this->request('PATCH', $url, $request_options);

It's the last request here that is failing and that is because $unparseable_request_body; contains !{>}< which ain't JSON

Status: Needs review » Needs work

The last submitted patch, 8: 2840974-8.patch, failed testing.

Wim Leers’s picture

But it's intentionally not JSON, hence $unparseable_request_body.

axot’s picture

Does this unparseable json test does not used POST method?

I create a patch for this case, could you test this?

diff --git a/sapi/apache2handler/sapi_apache2.c b/sapi/apache2handler/sapi_apache2.c
index 81574a4784..e8ccc49b7e 100644
--- a/sapi/apache2handler/sapi_apache2.c
+++ b/sapi/apache2handler/sapi_apache2.c
@@ -692,7 +692,11 @@ zend_first_try {
                brigade = ctx->brigade;
        }

-       if (SG(request_info).content_length > SG(read_post_bytes)) {
+       if (PG(enable_post_data_reading)
+       && SG(request_info).content_type
+       && SG(request_info).request_method
+       && !strcmp(SG(request_info).request_method, "POST")
+       && SG(request_info).content_length > SG(read_post_bytes)) {
                ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r, "Error while attempting to read POST data: %d", SG(sapi_headers).http_response_code);
                apr_brigade_cleanup(brigade);
                PHPAP_INI_OFF;
alexpott’s picture

@axot - yes it uses the PATCH method!

alexpott’s picture

axot’s picture

I tested the patch, it passed this test case, anyway the bugged commit was revert.

> sudo -u daemon php /usr/local/var/www/htdocs/core/scripts/run-tests.sh --color --keep-results --concurrency "3" --types "Simpletest,PHPUnit-Unit,PHPUnit-Kernel,PHPUnit-Functional" --url "http://localhost:8080/" --dburl "mysql://root@127.0.0.1/test" --sqlite "/tmp/simpleteststandard.sqlite" --class "Drupal\Tests\rest\Functional\EntityResource\User\UserJsonAnonTest"

Drupal test run
---------------

Tests to be run:
  - Drupal\Tests\rest\Functional\EntityResource\User\UserJsonAnonTest

Test run started:
  Thursday, January 5, 2017 - 17:02

Test summary
------------

Drupal\Tests\rest\Functional\EntityResource\User\UserJsonAno   4 passes

Test run duration: 42 sec

Thank you for reporting the issue, I will commit a new PR to PHP community soon.

Wim Leers’s picture

Thanks @axot!

catch’s picture

Title: EntityResourceTestBase tests fail randomly on PHP7 » EntityResourceTestBase tests fail on PHP7

So are we just waiting for the PHP 7 bot on DrupalCI to refresh with the latest commit?

Wim Leers’s picture

Yep.

Wim Leers’s picture

Title: EntityResourceTestBase tests fail on PHP7 » [blocked on PHP7] EntityResourceTestBase tests fail on PHP7
Issue tags: +Needs upstream bugfix, +php7
alexpott’s picture

Well we should still commit #8 but maybe once PHP7 is rebuilt it won't be critical.

Wim Leers’s picture

Yes, #8 looks great: it's a small correction. But I don't yet understand why this worked fine before and is only now a problem.

alexpott’s picture

@Wim Leers well obviously something in the PHP7 change made the PHP SAPI stricter.

catch’s picture

Title: [blocked on PHP7] EntityResourceTestBase tests fail on PHP7 » CookieResourceTestTrait tests should set Content-Type
Priority: Critical » Major
Status: Needs work » Needs review
Wim Leers’s picture

Status: Needs review » Reviewed & tested by the community
Issue tags: -Needs upstream bugfix, -php7

It looks like @catch has re-queued the test patch in #8.

If it comes back green, it's RTBC.

Wim Leers’s picture

I also added a 8.3.x test. Just making sure it passes there too.

Wim Leers’s picture

Title: CookieResourceTestTrait tests should set Content-Type » CookieResourceTestTrait test should send Content-Type request header
axot’s picture

Hi, I pushed a new PR to PHP community, (https://github.com/php/php-src/pull/2323)
It is great if we could retest this PR, is it possible?

Thank you.

Wim Leers’s picture

Done: re-testing with PHP 7, against 8.2.x (https://www.drupal.org/pift-ci-job/580021) and 8.3.x (https://www.drupal.org/pift-ci-job/580022)

Berdir’s picture

@Wim: That's not what axot asked for. He asked to compile PHP based on his PR and then run the tests against *that*. Locally, not on testbot, as testbot obviously can't do that.

Wim Leers’s picture

IIRC testbot is frequently updated to PHP 7 HEAD. I don't know how frequently though.

Berdir’s picture

It doesn't matter how recent HEAD is, it will not contain a PR that has not yet been merged :)

Wim Leers’s picture

D'oh, I overlooked that! My bad. Sorry for the noise.

axot’s picture

Thank you guys to follow up this,
I don't know how testbot works, if it could test the git HEAD of php,
Is it possible test a PR use these git commands?

git fetch origin pull/2323/head:test_branch
git checkout PHP-7.0
git merge --no-edit test_branch 
alexpott’s picture

@axot I've built PHP7 including your PR and the tests that were failing now pass. That's not to say there might be some other effect but at least this issue won't happen again.

axot’s picture

Thanks to test the PR @alexpott, could you test all the cases to confirm there are no more other side effects. Then we can merge this to PHP side.

Thank you.

alexpott’s picture

@axot if it was simple to run all test cases locally I would but it's not. We have far too many tests for that.

Wim Leers’s picture

@axot: if #36 sounds strange, here's a clarification: our test suite takes 26.5 minutes to run at concurrency 31 on the most powerful AWS machines: https://dispatcher.drupalci.org/job/default/308340/consoleFull. Running it locally takes hours.

axot’s picture

@alexpott @wim-leers That makes sense to me, so let we waiting for code review then.
Thank you.

  • catch committed 5394f9f on 8.4.x
    Issue #2840974 by alexpott, Wim Leers, axot: CookieResourceTestTrait...

  • catch committed 9866f44 on 8.3.x
    Issue #2840974 by alexpott, Wim Leers, axot: CookieResourceTestTrait...
catch’s picture

Status: Reviewed & tested by the community » Fixed

Committed/pushed to 8.4.x and 8.3.x, thanks!

@axot closing this issue since it deals with the Drupal part of this, thanks for the attention to the PHP bug!

Status: Fixed » Closed (fixed)

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

xjm’s picture