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

Noticed on #2627512: Datetime Views plugins don't support timezones #181.

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.

?