Drupal\KernelTests\Core\Entity\ContentEntityChangedTest::testChanged
When editing a non-translatable field the updated changed time is equal across all translations.
Failed asserting that 1487987261 matches expected 1487987260.

https://www.drupal.org/pift-ci-job/608035
https://www.drupal.org/pift-ci-job/615761
https://www.drupal.org/pift-ci-job/627979
https://www.drupal.org/pift-ci-job/661431
https://www.drupal.org/pift-ci-job/672309
https://www.drupal.org/pift-ci-job/681334
https://www.drupal.org/pift-ci-job/736994
https://www.drupal.org/pift-ci-job/742521
https://www.drupal.org/pift-ci-job/744664
https://www.drupal.org/pift-ci-job/750416
https://www.drupal.org/pift-ci-job/754089
https://www.drupal.org/pift-ci-job/758910
https://www.drupal.org/pift-ci-job/761965

Problem/Motivation

ChangedTestItem::preSave() uses time() instead of REQUEST_TIME. This leads to a fail in the ContentEntityChangedTest::testChanged, when the changes of entities occurs at the boundary between two seconds (see #15 with milliseconds outputs).
Example:

  • original instance has been changed in 1490000000,999
  • translation instance has been changed in 1490000001,000 (because it does not happen instantly)

It may seem that this is a rare fluke that is not worth the attention, but many examples lost RTBC status due to it.

Proposed resolution

Remaining tasks

User interface changes

API changes

Data model changes

Members fund testing for the Drupal project. Drupal Association Learn more

Comments

gambry created an issue. See original summary.

mpdonadio’s picture

Oddly, I thought this was a second rollover problem, but this doesn't seem to fail locally for me...

mpdonadio’s picture

Status: Active » Needs review
gambry’s picture

Maybe a specific problem from a specific comming?

I'm testing locally against 59b450939fe923baf5416a4d6bab742fdb5e68c0 , which looks like being last change on ContentEntityBase before that test ran on 24th of Feb.

gambry’s picture

I've tested patch on #2 against commits:

  • d837f01:
    Issue #2808335 by hchonov, tstoeckler, anish.a, Wim Leers, catch, Berdir: Changed time not updated when only non-translatable fields are changed on a translated entity
    22 February 2017 16:45:04 GMT
  • 59b4509:
    Issue #2854926 by xjm, himanshu-dixit, borisson_, boaloysius, alexpott: Remove unneeded control structures in ContentEntityBase
    23 February 2017 23:20:26 GMT
  • fafa49b:
    Issue #2854249 by GoZ, himanshu-dixit, boaloysius, xjm: Default message for linkNotExists and linkByHrefNotExists is wrong
    23 February 2017 11:09:38 GMT

To understand if was a failure due a regression / bugged new change (Test ran the 24th of Feb), but I couldn't replicate the error neither using sqlite nor mysql.

tacituseu’s picture

cilefen’s picture

Issue tags: +Triaged D8 critical

I discussed this issue with @xjm, @cottser, @catch, @alexpott and @lauriii. We agreed this should be critical because random fails tend to block other work.

xjm’s picture

This happened also in https://www.drupal.org/pift-ci-job/627979 and https://www.drupal.org/pift-ci-job/615761 (just to confirm it wasn't a one-off failure).

mpdonadio’s picture

Status: Needs review » Needs work

EntityTestMulChanged::save() has a sleep(1) in it, and ChangedTestItem::preSave() has a call out to time() in it. I'm scratching my head wondering if the combo of these is fragile. I am also wondering why both are needed?

rachel_norfolk’s picture

vaplas’s picture

Status: Needs work » Needs review
FileSize
1.16 KB

and ChangedTestItem::preSave() has a call out to time() in it

Looks like this is really catch! There are a lot of operations to accumulate the necessary number of milliseconds, allowing you to jump to the next second between calls of preSave() for each translation in ContentEntityStorageBase::invokeFieldMethod().

Status: Needs review » Needs work

The last submitted patch, 11: 2857843-11-test-only.patch, failed testing.

vaplas’s picture

On my local machine difference between two calls of preSave() (between translations entities) is 3 ms.
For proof of concept, that it can lead to 1 second a difference:

  • The first patch contains a payload (2000 additional languages).
  • The second patch is launched many times (x10000)

In both cases are used milliseconds (limited by the int type) instead of seconds in 'changed' value for more information.

Or #11 enough to confirm the reason of fail?

Status: Needs review » Needs work

The last submitted patch, 13: 10000_runs_2857843-13.patch, failed testing.

vaplas’s picture

Sorry. I forgot to turn off the second test (testRevisionChanged) and as a result 10000_runs always failed (I aborted CI). Also, 2000 languages clearly go beyond time limit (even php7 failed, who would have known :).

In order not to create unnecessary noise, I created a separate experiment for experiments. And this gave the results:

vaplas’s picture

Status: Needs work » Needs review
FileSize
2.47 KB
2.99 KB

Mini idea just round microseconds. This should give a reserve of 1 second. But I'm not sure how this will affect other tests.

vaplas’s picture

Okay. It was a stupid idea - threshold simply shifted from .999 to .499 :(
And looks like it is not fandom fail, because preSave() is called for each translations and as a result it can give different time value.

Status: Needs review » Needs work

The last submitted patch, 16: x1000_2857843-16.patch, failed testing.

mpdonadio’s picture

Status: Needs work » Needs review
FileSize
4.52 KB

I think this shows the problem. Gotta attach path first for dreditor.

Status: Needs review » Needs work

The last submitted patch, 19: 2857843-19-test-only.patch, failed testing.

mpdonadio’s picture

When I run locally:

$ ../vendor/bin/phpunit ../core/tests/Drupal/KernelTests/Core/Entity/ContentEntityChangedTest.php
PHPUnit 4.8.35 by Sebastian Bergmann and contributors.

F

Time: 9.53 seconds, Memory: 6.00MB

There was 1 failure:

1) Drupal\KernelTests\Core\Entity\ContentEntityChangedTest::testChanged
When editing a non-translatable field the updated changed time is equal across all translations. 1495242053
Failed asserting that 1495242062 matches expected 1495242061.

/Users/matt/Documents/PhpStorm/drupal-8.4.x/core/tests/Drupal/KernelTests/KernelTestBase.php:1176
/Users/matt/Documents/PhpStorm/drupal-8.4.x/core/tests/Drupal/KernelTests/Core/Entity/ContentEntityChangedTest.php:140

Here 1495242053 is the request time, and 1495242062 and 1495242061 and the changed times of the two entities we are mucking with.

+++ b/core/modules/system/tests/modules/entity_test/src/Plugin/Field/FieldType/ChangedTestItem.php
@@ -27,13 +27,23 @@ class ChangedTestItem extends ChangedItem {
+    if ($this->value === $this->getRequestTime()) {
       // During a test the request time is immutable. To allow tests of the
       // algorithm of
       // Drupal\Core\Field\Plugin\Field\FieldType\ChangedItem::preSave() we need
-      // to set a real time value here.
-      $this->value = time();
+      // to let time expire, and set a real time value here.
+      sleep(1);
+      $this->value = $this->getCurrentTime();
     }

Ok, here we are letting a second to pass to force so that the time() is always different when it gets called. Also notice that a whole bunch of time has passed in the test.

So, I think the problem is that getting the current time in this class is wrong. Instead we need to chase to the entity in original language and use its changed time instead of the current time.

Or, as I started to do with this patch, weave in the Time service, swap it out with test version so that we can adjust REQUEST_TIME through ContentEntityChangedTest.

?

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

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

vaplas’s picture

Repeating fails make one think about this assertion critically:

    // Update a non-translatable field to make sure that the changed timestamp
    // is updated for all translations.
    $entity->set('not_translatable', $this->randomString())->save();

    $this->assertTrue(
      $entity->getChangedTime() > $changed_en,
      'Changed time of original language did change.'
    );

    $this->assertTrue(
      $german->getChangedTime() > $changed_de,
      'Changed time of the German translation did change.'
    );

    $this->assertEquals($entity->getChangedTime(), $german->getChangedTime(), 'When editing a non-translatable field the updated changed time is equal across all translations.');

getChangedTime() returns the time in seconds. Therefore, by this assert (last in listing), we can at best be able to verify that the request for changing the $entity and $german in one second interval (that rather rough approximation).

Therefore, we can make:

  • variant 1: set the assert more loyal with comment (variant 1).
  • variant 2: add sleep to postSave, this ensures that the operation with all entities was one cycle (see ContentEntityStorageBase::invokeFieldMethod())
  • variant 3: forcibly wait for the beginning of a second for all original entities (this is looks better than coping original value to translation, otherwise what do we test?)

#21:

Or, as I started to do with this patch, weave in the Time service, swap it out with test version so that we can adjust REQUEST_TIME through ContentEntityChangedTest.

Sounds nice irrespective of this issue!

Status: Needs review » Needs work

The last submitted patch, 23: v3-2857843-23.patch, failed testing. View results

vaplas’s picture

Status: Needs work » Needs review
FileSize
1.13 KB
899 bytes
gambry’s picture

Worth having a look at: https://stackoverflow.com/questions/43499771/php-time-sleep-until-does-n...

And the different value of time() and microtime() when time_sleep_until() is used.

Proof:
time_sleep_until($waituntil);
echo "Now: ".microtime(true)."\n";
echo "Now: ".time()."\n";

gives me

Wait until: 1492615871
Now: 1492615871.0001
Now: 1492615870

vaplas’s picture

Thank you @gambry! This is useful. I tried to play with microtime(true) & usleep(). But the code is more complicated because of this. Like this:

      $microtime_left = microtime(true);
      $P = 1000000;
      $step = ($P - ($microtime_left * $P) % $P) / $P;
      $wait = $microtime_left + $step;
      time_sleep_until($wait);
...
      $this->value = round(microtime(true));

So I left a more rude, but readable code:
time_sleep_until(time() + 1.1);

vaplas’s picture

Sorry, it was example with microtime + time_sleep_until, but with usleep it works also unstable (just change time_sleep_until($wait) to usleep($step))

mpdonadio’s picture

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

I think I like #25.

catch’s picture

Status: Needs review » Needs work

#25 looks good to me as well. Couple of suggestions on the comments:

  1. +++ b/core/modules/system/tests/modules/entity_test/src/Plugin/Field/FieldType/ChangedTestItem.php
    @@ -31,7 +31,13 @@ public function preSave() {
    -      // to set a real time value here.
    +      // to set a real time value here. But for the stability of the test,
    +      // change the entity with the original language at the beginning of the
    +      // second. Comply with this requirement on real sites do not need to.
    

    Would reword the comment to:

    "For the stability of the test, set the time of the original language to the current time plus just over one second to simulate two different request times. @todo mock the time service in [issue]"
    Let's open an issue for using the time service too and link to that.

  2. +++ b/core/modules/system/tests/modules/entity_test/src/Plugin/Field/FieldType/ChangedTestItem.php
    @@ -31,7 +31,13 @@ public function preSave() {
    +        // Wait 1.1 second's, because time_sleep_until works not very accurate.
    

    Wait 1.1 seconds because time_sleep_until() is not reliable.

Jo Fitzgerald’s picture

Assigned: Unassigned » Jo Fitzgerald
Jo Fitzgerald’s picture

Assigned: Jo Fitzgerald » Unassigned
Status: Needs work » Needs review
FileSize
1.19 KB
1.44 KB

Made both changes requested by @xjm in #30 including opening an issue for using the time service: #2908210: Use the time service in Drupal\entity_test\Plugin\Field\FieldType\ChangedTestItem.

vaplas’s picture

Thank you, @catch and @Jo Fitzgerald for review and help with it.

+++ b/core/modules/system/tests/modules/entity_test/src/Plugin/Field/FieldType/ChangedTestItem.php
@@ -31,11 +31,12 @@ public function preSave() {
-      // to set a real time value here. But for the stability of the test,
-      // change the entity with the original language at the beginning of the
-      // second. Comply with this requirement on real sites do not need to.
+      // to set a real time value here. For the stability of the test, set the
+      // time of the original language to the current time plus just over one
+      // second to simulate two different request times.

It looks much better, but the one who will read this can have several questions:

  1. Why we need "simulate two different request times" only for original entities instead of all entities?
  2. Why we wait here, if we already wait in EntityTestMulChanged::save() via sleep(1)?

In fact, we care here precisely for the processing of all translations in the same second as the original instance.
Example:

  • original instance has been changed in 1490000000,999
  • translation instance has been changed in 1490000001,000 (because it does not happen instantly)

As a result, the difference is one second, which leads to a fail in the test.

After patch we have:

  • a guarantee of about 100 milliseconds on the left (time_sleep_until() is not reliable near 1-3ms)
  • a guarantee of about 900 milliseconds on the right (translation processing near 1ms on d.org CI)

This is only necessary for the test system, because it uses time() instead of REQUEST_TIME.

vaplas’s picture

Issue summary: View changes

#33: What I wanted to say is that perhaps the commentary can be even clearer. But maybe not. The question of this does not block the issue. Whoever wants, will reads the issue in which these lines appeared :)

+1 to RTBC.

vaplas’s picture

And yep, #30 comment makes a lot of sense for another random fail https://www.drupal.org/pift-ci-job/743965:

Drupal\KernelTests\Core\Entity\ContentEntityChangedTest::testRevisionChanged
Changed time of original language has been updated by new revision.
Failed asserting that false is true.

We haven't issue for this fail, but the shortage of the current fix (additional wait of 1 second) should help with its. Woot!

mpdonadio’s picture

I think #36 demonstrates that the current patch will at least help with test stability, if not fix this problem outright.

Took another look at latest patch, and think it is OK. Reviewed file list, and I only had a few test-only patches on the issue, so my hands are clean. Let's do it.

catch’s picture

Status: Reviewed & tested by the community » Fixed

I tried to think of a clearer comment but couldn't, and we have the time service follow-up which should make things a bit more self-explanatory anyway.

Committed/pushed to 8.5.x and cherry-picked to 8.4.x. Thanks!

  • catch committed 8265b77 on 8.5.x
    Issue #2857843 by vaplas, mpdonadio, Jo Fitzgerald, gambry: Random fail...

  • catch committed 650c701 on 8.4.x
    Issue #2857843 by vaplas, mpdonadio, Jo Fitzgerald, gambry: Random fail...

Status: Fixed » Closed (fixed)

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