Problem/Motivation

https://www.drupal.org/pift-ci-job/576062

Drupal\Tests\rest\Functional\EntityResource\Term\TermJsonAnonTest
exception: [Other] Line 0 of sites/default/files/simpletest/phpunit-1619.xml:
PHPunit Test failed to complete; Error: PHPUnit 4.8.27 by Sebastian Bergmann and contributors.

...E

Time: 2.82 minutes, Memory: 3.25Mb

There was 1 error:

1) Drupal\Tests\rest\Functional\EntityResource\Term\TermJsonAnonTest::testDelete
GuzzleHttp\Exception\ConnectException: cURL error 28: Operation timed out after 30001 milliseconds with 0 bytes received (see http://curl.haxx.se/libcurl/c/libcurl-errors.html)

/var/www/html/vendor/guzzlehttp/guzzle/src/Handler/CurlFactory.php:186
/var/www/html/vendor/guzzlehttp/guzzle/src/Handler/CurlFactory.php:150
/var/www/html/vendor/guzzlehttp/guzzle/src/Handler/CurlFactory.php:103
/var/www/html/vendor/guzzlehttp/guzzle/src/Handler/CurlHandler.php:43
/var/www/html/vendor/guzzlehttp/guzzle/src/Handler/Proxy.php:28
/var/www/html/vendor/guzzlehttp/guzzle/src/Handler/Proxy.php:51
/var/www/html/core/lib/Drupal/Core/Test/HttpClientMiddleware/TestHttpClientMiddleware.php:31
/var/www/html/vendor/guzzlehttp/guzzle/src/PrepareBodyMiddleware.php:42
/var/www/html/vendor/guzzlehttp/guzzle/src/Middleware.php:36
/var/www/html/vendor/guzzlehttp/guzzle/src/RedirectMiddleware.php:52
/var/www/html/vendor/guzzlehttp/guzzle/src/Middleware.php:59
/var/www/html/vendor/guzzlehttp/guzzle/src/HandlerStack.php:67
/var/www/html/vendor/guzzlehttp/guzzle/src/Client.php:275
/var/www/html/vendor/guzzlehttp/guzzle/src/Client.php:123
/var/www/html/vendor/guzzlehttp/guzzle/src/Client.php:129
/var/www/html/vendor/fabpot/goutte/Goutte/Client.php:138
/var/www/html/vendor/symfony/browser-kit/Client.php:315
/var/www/html/vendor/symfony/browser-kit/Client.php:499
/var/www/html/vendor/symfony/browser-kit/Client.php:331
/var/www/html/vendor/behat/mink-browserkit-driver/src/BrowserKitDriver.php:144
/var/www/html/vendor/behat/mink/src/Session.php:143
/var/www/html/core/tests/Drupal/Tests/BrowserTestBase.php:372
/var/www/html/core/tests/Drupal/Tests/BrowserTestBase.php:475
/var/www/html/core/modules/rest/tests/src/Functional/ResourceTestBase.php:101
/var/www/html/core/modules/rest/tests/src/Functional/EntityResource/EntityResourceTestBase.php:154

FAILURES!
Tests: 4, Assertions: 137, Errors: 1.

There are some errors in https://dispatcher.drupalci.org/job/default/302253/artifact/jenkins-defa... about

[Tue Jan 17 23:31:31.337775 2017] [:error] [pid 8424] [client ::1:48067] Uncaught PHP Exception Drupal\\Core\\Database\\DatabaseExceptionWrapper: "SQLSTATE[42S02]: Base table or view not found: 1146 Table 'jenkins_default_302253.test81513819key_value' doesn't exist: SELECT 1 AS expression\nFROM \n{key_value} key_value\nWHERE ( (name = :db_condition_placeholder_0) AND (collection = :db_condition_placeholder_1) ); Array\n(\n    [:db_condition_placeholder_0] => system.theme.files\n    [:db_condition_placeholder_1] => state\n)\n" at /var/www/html/core/lib/Drupal/Core/Database/Connection.php line 671, referer: http://localhost/checkout

That are not present in successful test runs. Not sure if they are related.

This test fail was also noted in #2829040-9: [meta] Known intermittent, random, and environment-specific test failures / https://www.drupal.org/pift-ci-job/535086 so it has been happening for a while.

Proposed resolution

Remaining tasks

User interface changes

API changes

Data model changes

Comments

alexpott created an issue. See original summary.

alexpott’s picture

alexpott
he/they
Primary language English
Location 🇪🇺🌍
commented

Reading the backtrace it is the first request to the site that is failing... from \Drupal\Tests\BrowserTestBase::initMink

    // According to the W3C WebDriver specification a cookie can only be set if
    // the cookie domain is equal to the domain of the active document. When the
    // browser starts up the active document is not our domain but 'about:blank'
    // or similar. To be able to set our User-Agent and Xdebug cookies at the
    // start of the test we now do a request to the front page so the active
    // document matches the domain.
    // @see https://w3c.github.io/webdriver/webdriver-spec.html#add-cookie
    // @see https://www.w3.org/Bugs/Public/show_bug.cgi?id=20975
    $session = $this->getSession();
    $session->visit($this->baseUrl);
wim leers’s picture

wim leers
Location Ghent 🇧🇪🇪🇺
commented

#2829040-9: [meta] Known intermittent, random, and environment-specific test failures and https://www.drupal.org/pift-ci-job/535086 fail in Drupal\Tests\standard\Functional\StandardTest, not EntityResourceTestBase.

#2832853: Random fail in hal EntityTestHalJsonAnonTest::testPost via rest EntityResourceTestBase::testPost was more related, but it was closed again since it was no longer reproducible.

But clearly, https://www.drupal.org/pift-ci-job/576062 is failing in EntityResourceTestBase. Specifically on testDelete() only. Specifically for these tests:

  • CommentJsonCookieTest::testDelete()
  • TermJsonAnonTest::testDelete()
  • TermJsonBasicAuthTest::testDelete()
  • TermJsonCookieTest::testDelete()
  • UserJsonBasicAuthTest::testPatch -> so apparently also testPatch()
  • UserJsonCookieTest::testPatch()

So:

  1. Taxonomy Term + JSON is failing in the delete test, for all authentication mechanisms
  2. User + JSON is failing in the patch test, but not when not using any authentication (anonymous)
  3. Comment + JSON is failing in the delete test, but not for basic auth or anon

I'm not yet seeing any pattern :(

Looking at the build artifacts at https://dispatcher.drupalci.org/job/default/302253/artifact/jenkins-defa..., I don't see anything special. There are four uncaught PHP exceptions logged:

[Tue Jan 17 23:31:31.337775 2017] [:error] [pid 8424] [client ::1:48067] Uncaught PHP Exception Drupal\\Core\\Database\\DatabaseExceptionWrapper: "SQLSTATE[42S02]: Base table or view not found: 1146 Table 'jenkins_default_302253.test81513819key_value' doesn't exist: SELECT 1 AS expression\nFROM \n{key_value} key_value\nWHERE ( (name = :db_condition_placeholder_0) AND (collection = :db_condition_placeholder_1) ); Array\n(\n    [:db_condition_placeholder_0] => system.theme.files\n    [:db_condition_placeholder_1] => state\n)\n" at /var/www/html/core/lib/Drupal/Core/Database/Connection.php line 671, referer: http://localhost/checkout
[Tue Jan 17 23:31:31.341602 2017] [:error] [pid 10364] [client ::1:48068] Uncaught PHP Exception Drupal\\Core\\Database\\DatabaseExceptionWrapper: "SQLSTATE[42S02]: Base table or view not found: 1146 Table 'jenkins_default_302253.test51779714key_value' doesn't exist: SELECT 1 AS expression\nFROM \n{key_value} key_value\nWHERE ( (name = :db_condition_placeholder_0) AND (collection = :db_condition_placeholder_1) ); Array\n(\n    [:db_condition_placeholder_0] => system.theme.files\n    [:db_condition_placeholder_1] => state\n)\n" at /var/www/html/core/lib/Drupal/Core/Database/Connection.php line 671, referer: http://localhost/checkout
[Tue Jan 17 23:31:31.446427 2017] [:error] [pid 10453] [client ::1:48078] Uncaught PHP Exception Drupal\\Core\\Database\\DatabaseExceptionWrapper: "SQLSTATE[42S02]: Base table or view not found: 1146 Table 'jenkins_default_302253.test14501989key_value' doesn't exist: SELECT 1 AS expression\nFROM \n{key_value} key_value\nWHERE ( (name = :db_condition_placeholder_0) AND (collection = :db_condition_placeholder_1) ); Array\n(\n    [:db_condition_placeholder_0] => system.theme.files\n    [:db_condition_placeholder_1] => state\n)\n" at /var/www/html/core/lib/Drupal/Core/Database/Connection.php line 671, referer: http://localhost/checkout
[Tue Jan 17 23:31:31.490976 2017] [:error] [pid 10342] [client ::1:48072] Uncaught PHP Exception Drupal\\Core\\Database\\DatabaseExceptionWrapper: "SQLSTATE[42S02]: Base table or view not found: 1146 Table 'jenkins_default_302253.test66126467key_value' doesn't exist: SELECT 1 AS expression\nFROM \n{key_value} key_value\nWHERE ( (name = :db_condition_placeholder_0) AND (collection = :db_condition_placeholder_1) ); Array\n(\n    [:db_condition_placeholder_0] => system.theme.files\n    [:db_condition_placeholder_1] => state\n)\n" at /var/www/html/core/lib/Drupal/Core/Database/Connection.php line 671, referer: http://localhost/checkout

And those 4 all occur at 23:31:31, multiple times during that one second. But the failing tests happen at 23:31:22, 23:31:24, 23:31:26, 23:31:28 and 23:31:37. So there doesn't seem to be any correlation.

I have no idea.

Note that it's a network timeout. So I'd actually look at DrupalCI, not at the code. No assertion has failed.

alexpott’s picture

alexpott
he/they
Primary language English
Location 🇪🇺🌍
commented

Also it looks like the default timeout for our Guzzle client is set in \Drupal\Core\Http\ClientFactory::fromOptions()

    $default_config = [
      // Security consideration: we must not use the certificate authority
      // file shipped with Guzzle because it can easily get outdated if a
      // certificate authority is hacked. Instead, we rely on the certificate
      // authority file provided by the operating system which is more likely
      // going to be updated in a timely fashion. This overrides the default
      // path to the pem file bundled with Guzzle.
      'verify' => TRUE,
      'timeout' => 30,
      'headers' => [
        'User-Agent' => 'Drupal/' . \Drupal::VERSION . ' (+https://www.drupal.org/) ' . \GuzzleHttp\default_user_agent(),
      ],
      'handler' => $this->stack,
      // Security consideration: prevent Guzzle from using environment variables
      // to configure the outbound proxy.
      'proxy' => [
        'http' => NULL,
        'https' => NULL,
        'no' => [],
      ]
    ];
alexpott’s picture

alexpott
he/they
Primary language English
Location 🇪🇺🌍
commented

WebTestBase looks as though we're using the defaults... https://stackoverflow.com/questions/10308915/php-default-curl-timeout-value which are much larger.

wim leers’s picture

wim leers
Location Ghent 🇧🇪🇪🇺
commented

But do we really want it to be higher than 30? I'd want to set it to 10 or so…

alexpott’s picture

alexpott
he/they
Primary language English
Location 🇪🇺🌍
commented

So I propose we backport #2784159: Remove CURL timeout in BTB since I've not seen this fail in 8.3.x

wim leers’s picture

wim leers
Location Ghent 🇧🇪🇪🇺
commented
Related issues: +#2784159: Remove CURL timeout in BTB

I see you posted a patch at #2784159-12: Remove CURL timeout in BTB to do exactly that.

If that's what it takes, if our testing infrastructure is unpredictable, then sure! And you're right that you want a higher timeout for debugging anyway (i.e. stepping through it with xdebug).

alexpott’s picture

alexpott
he/they
Primary language English
Location 🇪🇺🌍
commented
Title: Random fails in EntityResource tests with Operation timed out after 30001 milliseconds with 0 bytes » Random fails in BrowserTestBase tests with Operation timed out after 30001 milliseconds with 0 bytes
Status: Active » Fixed

I'm going to mark this as fixed now that #2784159: Remove CURL timeout in BTB has landed. We should re-open if we see this again.

xjm’s picture

xjm
she/her
Primary language English
commented
Parent issue: #2829040: [meta] Known intermittent, random, and environment-specific test failures »

Status: Fixed » Closed (fixed)

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