Problem/Motivation

Random fail in Drupal\page_cache\Tests\PageCacheTest:: testPageCacheAnonymous403404()

fail: [Other] Line 386 of core/modules/page_cache/src/Tests/PageCacheTest.php:
The cache entry expiry time uses the cache_ttl_4xx setting.

See https://www.drupal.org/pift-ci-job/583247
https://www.drupal.org/pift-ci-job/584350

Proposed resolution

Remaining tasks

User interface changes

API changes

Data model changes

Problem/Motivation

Proposed resolution

Remaining tasks

User interface changes

API changes

Data model changes

CommentFileSizeAuthor
#18 2847268-18.patch984 bytestacituseu
#15 2847268-15.patch922 bytestacituseu
#4 2847268-4.patch664 bytesalexpott
Support from Acquia helps fund testing for Drupal Acquia logo

Comments

alexpott created an issue. See original summary.

alexpott’s picture

alexpott
he/they
Primary language English
Location 🇪🇺🌍
CreditAttribution: alexpott at Chapter Three commented
Parent issue: » #2829040: [meta] Known intermittent, random, and environment-specific test failures
alexpott’s picture

alexpott
he/they
Primary language English
Location 🇪🇺🌍
CreditAttribution: alexpott at Chapter Three commented

This could easily be a timing issue...

      // Ensure the 'expire' field on the cache entry uses cache_ttl_4xx.
      $cache_item = \Drupal::service('cache.render')->get($this->getUrl() . ':html');
      $difference = $cache_item->expire - (int) $cache_item->created;
      // Given that a second might have passed we cannot be sure that
      // $difference will exactly equal the default cache_ttl_4xx setting.
      // Account for any timing difference or rounding errors by ensuring the
      // value is within 5 seconds.
      $this->assertTrue(
        $difference > $cache_ttl_4xx - 5 &&
        $difference < $cache_ttl_4xx + 5,
        'The cache entry expiry time uses the cache_ttl_4xx setting.'
      );
alexpott’s picture

alexpott
he/they
Primary language English
Location 🇪🇺🌍
CreditAttribution: alexpott at Chapter Three commented
Status: Active » Needs review
FileSize
2847268-4.patch664 bytes

Let's add some info to the assertion message to help us.

Pass      Other      PageCacheTest.php  385 Drupal\page_cache\Tests\PageCacheTe
    The cache entry expiry time uses the cache_ttl_4xx setting. Expire:
    1485528129 Created: 1485524529.176
pwolanin’s picture

pwolanin CreditAttribution: pwolanin as a volunteer and at SciShield commented

Sporadic fail here: https://www.drupal.org/pift-ci-job/583247

Version: 8.3.x-dev » 8.4.x-dev

Drupal 8.3.0-alpha1 will be released the week of January 30, 2017, which means new developments and disruptive changes should now be targeted against the 8.4.x-dev branch. For more information see the Drupal 8 minor version schedule and the Allowed changes during the Drupal 8 release cycle.

  • catch committed 4e4833b on 8.4.x 
    Issue #2847268 by alexpott: Random fail in Drupal\page_cache\Tests\...

  • catch committed 57522e2 on 8.3.x 
    Issue #2847268 by alexpott: Random fail in Drupal\page_cache\Tests\...
catch’s picture

catch
he/him
Primary language English
CreditAttribution: catch at Third and Grove commented

Committed the better assertion message to aid debugging.

tacituseu’s picture

tacituseu CreditAttribution: tacituseu commented

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

fail: [Other] Line 386 of core/modules/page_cache/src/Tests/PageCacheTest.php:
The cache entry expiry time uses the cache_ttl_4xx setting. Expire: 1485617538 Created: 1485613944.835

$difference = $cache_item->expire - (int) $cache_item->created; // (= 3594)

dawehner’s picture

dawehner
Primary language German
CreditAttribution: dawehner as a volunteer and at Chapter Three commented

We could increase this offset from 5 to 15 seconds. The actual page cache system is quite unit tested in \Drupal\page_cache\StackMiddleware\PageCache so we don't really necessarily loose a lot of test coverage with doing so. Increasing the number to 15 seconds would dramatically decrease the probability for random failures.

xjm’s picture

xjm
she/her
Primary language English
CreditAttribution: xjm at Acquia commented
Issue summary: View changes

Adding the HEAD failure to the summary to demonstrate it's not just an issue with a patch.

tacituseu’s picture

tacituseu CreditAttribution: tacituseu commented

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

fail: [Other] Line 386 of core/modules/page_cache/src/Tests/PageCacheTest.php:
The cache entry expiry time uses the cache_ttl_4xx setting. Expire: 1485646724 Created: 1485643130.632

$difference = 3594;

dawehner’s picture

dawehner
Primary language German
CreditAttribution: dawehner as a volunteer and at Chapter Three commented

@tacituseu
I guess 6 seems basically the maximum we get in random test failures, so maybe increasing the different to 10 would already be enough?

tacituseu’s picture

tacituseu CreditAttribution: tacituseu commented
FileSize
2847268-15.patch922 bytes

Couldn't find more instances.

dawehner’s picture

dawehner
Primary language German
CreditAttribution: dawehner as a volunteer and at Chapter Three commented
Status: Needs review » Reviewed & tested by the community

10 seconds work for me

Status: Reviewed & tested by the community » Needs work

The last submitted patch, 15: 2847268-15.patch, failed testing.

tacituseu’s picture

tacituseu CreditAttribution: tacituseu commented
Status: Needs work » Needs review
FileSize
2847268-18.patch984 bytes

Patch against HEAD this time ;)

The last submitted patch, 15: 2847268-15.patch, failed testing.

tacituseu’s picture

tacituseu CreditAttribution: tacituseu commented
Status: Needs review » Reviewed & tested by the community

Just a re-roll so back to RTBC per #16.
BTW in https://www.drupal.org/pift-ci-job/585026 patch failed to apply, yet all the tests ran anyway, seen it a couple of times now.
Also reasoning behind 10 seconds is: 6-7 is extreme case and doesn't occur often, caused by high concurrency on testbot, if it gets any slower would be good to know/trip anyway.

tacituseu’s picture

tacituseu CreditAttribution: tacituseu commented

https://www.drupal.org/pift-ci-job/584529
The cache entry expiry time uses the cache_ttl_4xx setting. Expire: 1485653810 Created: 1485650215.513
$difference = 3595;

Could someone re-trigger default branch for 8.4.x-dev ? It's stalling issues for more than a day now.
https://www.drupal.org/node/3060/qa

  • catch committed cae18a3 on 8.4.x 
    Issue #2847268 by tacituseu, alexpott, dawehner: Random fail in Drupal\...

  • catch committed bc2c44a on 8.3.x 
    Issue #2847268 by tacituseu, alexpott, dawehner: Random fail in Drupal\...
catch’s picture

catch
he/him
Primary language English
CreditAttribution: catch at Third and Grove commented
Version: 8.4.x-dev » 8.3.x-dev
Status: Reviewed & tested by the community » Fixed

Committed/pushed to 8.4.x and 8.3.x.

Doesn't apply to 8.2.x but since it's test-only, I think we can leave this at 8.3.x.

tacituseu’s picture

tacituseu CreditAttribution: tacituseu commented

#15 has patch that applies to 8.2.x

xjm’s picture

xjm
she/her
Primary language English
CreditAttribution: xjm at Acquia 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.

tacituseu’s picture

tacituseu CreditAttribution: tacituseu commented

Well..
https://www.drupal.org/pift-ci-job/600319

fail: [Other] Line 387 of core/modules/page_cache/src/Tests/PageCacheTest.php:
The cache entry expiry time uses the cache_ttl_4xx setting. Expire: 1487215420 Created: 1487211830.929

$difference = 3590