Drupal\system\Tests\Entity\EntityQueryTest random failure

I checked and head is (at least right now) green:
https://qa.drupal.org/8.x-status

this made me think it would be nice to see what previous test results were..
which I guess is #1350592: Link to previous results on qa.drupal.org

Well, what Berdir is talking about (I think) is #2235111: EntityQueryTest is fragile, but that has been fixed for a while. :-/

I had to dig into that test for quite a few hours when finding that one, though, so maybe I can revive that knowledge. :-) Will look into this in the next few days.

Edit: And even thought the referenced issue fixed one problem with that test it is still incredibly messed up. So it does not surprise me even a bit that there might be a random failure here. Since this is already the second issue dedicated to that one test, we should really try to fix the test properly this time. We'll see...

So sorry for not providing feedback earlier, here is as far as I got with debugging this test.

EntityQueryTest in fact does not fail randomly in 8.x, but only in combination with #2239399: Languages should be sorted by label instead of title. With that applied it fails roughly 30%-40% of the time (although I did not investigate the percentage very thoroughly). I am not closing this one, though, and fixing it there, as debugging has revealed what looks like at least one very strange bug, which should be fixed independently. So let's decide what to do with this issue only once we have truely figured out WTH is going on here. :-)

First of all I checked that Drupal\Core\Language\Language::sort() is in fact being called from EntityQueryTest as that is the only non-test code that is being touched there. ...It is. Example call-chain:

• Drupal\language\Entity\Language::preSave()
• Drupal\language\ConfigurableLanguageManager::isMultilingual()
• Drupal\language\ConfigurableLanguageManager::getLanguages()
• Drupal\Core\Language\Language::sort()

So it is at least proven to be possible for that issue to influence this test.

Then I started looking at the actual test failures starting with the first. It is in line 259 of EntityQueryTest. There it asserts that field revisions with the value merhaba can be loaded. Before, it has inserted entities with the field value merhaba but then created new revisions of those entities with the field values xsiemax. So in theory the new field values should be saved with a new revision ID and the old values are still accessible. I found out when checking the database at the appropriate times, that in fact the original merhaba values are being overwritten, with the xsiemax values. Therefore the old values cannot be loaded anymore (they are not in the database!) and thus the assertion fails.

I then pinpointed the problem to line 789 of ContentEntityDatabaseStorage::doSaveFieldItems(). There the revision ID to save the field items under is being fetched by calling $entity->getRevisionId(). I confirmed that while this should have been the new revision ID of the just saved revision it is still the old revision ID. I also confirmed that the new revision is being properly created in the base table and a new revision ID is being created.

So how can $entity->getRevisionId() return a wrong result? ContentEntityBase has an $entityKeys member variable which acts as a cache for entity key values, among which is the revision ID. It turns out that at the given point in code $entity->entityKeys['revision'] is still populated with the old value.

Then I looked at line 702 in ContentEntityDatabaseStorage::saveRevision(). There the revision ID of the entity is being set explicitly. In following the code flow of that line with a debugger I found the following:

• The setting of the value through the use of magic __get() and __set() functions makes its way through the typed data API and eventually ends up in Drupal\Core\TypedData\Plugin\DataType\Integer::setValue() which is inherited from Drupal\Core\TypedData\PrimitiveBase::setValue().
• Because $notify is TRUE (the default value) this makes its way back up in the typed data path. First in line is Drupal\Core\Field\FieldItemBase::onChange(), next up Drupal\Core\TypedData\Plugin\DataType\ItemList::onChange() and lastly Drupal\Core\Entity\ContentEntityBase::onChange().
• If $property_name is the name of an entity key ContentEntityBase::onChange() unsets the appropriate values in $this->entityKeys.

So then I checked again but - as I had found out previously - the old value is still present in $entity->entityKeys later in ContentEntityDatabaseStorage::doSaveFieldItems(). How can that be?

I then checked whether the $entity that gets passed through ContentEntityDatabaseStorage and the entity on which onChange() is called from the above call chain are in fact the same objects. I then found out that this was in fact not the case. So the old value is being unset, but on the wrong object.

So it seems that $this->parent gets set incorrectly at some point. I did not completely pinpoint this issue but I did find out the following:

• TypedDataManager::createPropertyInstance() is responsible for creating all those objects from the above chain, i.e. FieldItemList (which extends ItemList), IntegerItem (which extends FieldItemBase) and Integer (which extends PrimitiveBase.
• TypedDataManager::createPropertyInstance() calls $property = clone $this->prototypes[$key] (where $property ends up being returned from the method). After performing the clone $property->parent is set by calling $property->setContext(). So during the clone $property still has whatever it had before as $this->parent.
• For (Field)ItemList, cloning goes through the magic method ItemList::__clone() which clones each of its field items in the same way. It performs a clone $item and then calls setContext() on the new object to properly set the parent variable. However - as noted above - the item list still has the wrong parent at this point.

This is where I stopped the debugging due to real life/sanity constraints. I don't yet know

• If the cloning is in fact the problematic part at all.
• If this is the problem, why the later call to setContext() on the item list does not update what is contained in IntegerItem::parent as those should be the same object as well.
• Why this happens only sometimes.
• What this has to do with Drupal\Core\Language\Language::sort().

Edit: Fix markup
Edit 2: Minor typo/wording fixes
Edit 3: Minor typo/wording fixes
Edit 4: Minor code fixes

Well, prior versions of #2239399: Languages should be sorted by label instead of title attempted to use a nonexistent entity property which may have ignited the property lookup process in entities. Did you verify this with the latest patch in #2239399: Languages should be sorted by label instead of title?

Yup, see #2239399-46: Languages should be sorted by label instead of title. Still fails randomly (70%-80%) with the latest patch there.

#2226533: Changes to the Language class due to the LanguageInterface (followup)
Is also getting random EntityQueryTest failures with its patch.

Ahh the benefits of an inquiring mind who is across all issues thanks YesCT.

So I am coming from #2226533: Changes to the Language class due to the LanguageInterface (followup) where this exact failure been a recurring problem....

I have been stepping through with a debugger, inspecting variables as I went BUT always when debugging the failing tests passed!
... tstoeckler's comments in #7, from this issue, can be read as debugging will be impossible without a carefully thought out strategy that
considers when the magic get functions may and may not be called and when they will disturb the measurement...

If I can express one of YestCT's ideas in my own words...
We need to reason this bug out, to identify and fix the brittle areas of the system, and that can only be done by pooling failure points from many different errant test while dealing with the fact these were fundamentally broken tests for other reasons, and in any event they reflect the way HEAD once was, not as it is now.

So I am going to make notes on #2226533: Changes to the Language class due to the LanguageInterface (followup) in public and reference testbot results wherever possible..

While the comings and goings of EntityQueryTests may appear intermittent.. I think there maybe something more useful to say ..
I think there were step up points where the tests started reliably failing, for a time, and corresponding step down points where the problem disappeared for a time...
and so on..

I see 5 failing test form EntityQueryTest First appearing in #73 - https://qa.drupal.org/pifr/test/790058 - ( although I can't confirm they are the exact same 5 because the testbot report is limited. )

#83 https://qa.drupal.org/pifr/test/790233 is the first point where details of entityQueryTest can be inspected to prove that those 5 are exactly the failing tests from this issue.

#85 is a transition event ??? ( https://qa.drupal.org/pifr/test/790238 ) here the failing EntityQueryTests have magically healed themselves.

#87 EntityQueryTests failing hardly a unbroken spell as I maintain ... but a data point.

#110 EntityQueryTest passes https://qa.drupal.org/pifr/test/791103

#113 EntityQueryTest fails https://qa.drupal.org/pifr/test/791143

#110 to #113 is an interesting transition as diffing patch should result in only a small changes. but for now I am just making notes...

#116 EntityQueryTest fails

#120 EntityQueryTests fails

#122 EntityQueryTest passes. ( https://qa.drupal.org/pifr/test/791903 )

#126 EntityQueryTests fails ( https://qa.drupal.org/pifr/test/792183 )

#129 EntityQueryTest fails ( https://qa.drupal.org/pifr/test/792483 )

#141 EntityQueryTests passes ( https://qa.drupal.org/pifr/test/793273 )

#147 entityQueryTest passes ( https://qa.drupal.org/pifr/test/793753 )

#151 entityQueryTest fails ( https://qa.drupal.org/pifr/test/794643 )

#153 entityQueryTest fails
...
..

.. skipping forward to an interesting issue #195

I was using php5.5 and locally I could get the EntityQueryTests to repeatedly flip between pass and fail while changing a buggy line
in the function language_access_language_edit_or_delete($language) see language.module
At that point it was not intermittent ( ie identical results when repeating the same test... and it needed a change in code to flip )

The tricky thing was I could not repeat this on a php5.4 testbot...I reasoned it would be tricky to solve so I moved onto other failing tests. hmmm

I am at the end of the time, I can spend on this today, I hope this is food for thought... I need to be convinced of my intermittently switching theory,
Looking back I certainly have not presented any convincing evidence...

Next week I will try and find time to analyse these results properly.

@martin107 suppose php version makes sense, I got a lot of trouble with current core under 5.5.3 and downgrade to 5.4 or upgrade 5.5.9 helps
So it possible that flux is caused by specific php version, a year ago the similar trouble with ordering happens in #1981418: Drop taxonomy_vocabulary_sort()

Returning to #11 where I am looking for a thread common to at least some of the pass/fail transitions.

looking a

#110 EntityQueryTest passes ... to Query the language lock it used the form !$language->isLocked()

#113 EntityQueryTest fails .. it uses the form !empty($language->locked)

So

A There s a cautionary tale to tell about the difference between php5.4 and php5.5 regarding the use of the empty() function.
https://www.drupal.org/node/2226533#comment-8900699
http://stackoverflow.com/questions/1075534/cant-use-method-return-value-...

B There is a change between public access to a property ( locked ) vs. getter functions calls to a private property

C !empty($language->locked) is the inverse of !$language->isLocked()

Looking at a diff between patches in 185-> 191

185 EntiyQueryTest PASS
188 REROLL
191 EntityQueryTest FAIL

has a few other changes but this one attracted my attention

> function content_translation_translate_access(EntityInterface $entity) {
> - return $entity instanceof ContentEntityInterface && empty($entity->getUntranslated()->language()->locked) && \Drupal::languageManager()->isMultilingual() && $entity->isTranslatable() &&
> + return $entity instanceof ContentEntityInterface && !$entity->getUntranslated()->language()->isLocked() && \Drupal::languageManager()->isMultilingual() && $entity->isTranslatable() &&
> (user_access('create content translations') || user_access('update content translations') || user_access('delete content translations'));
> }

A, B, C all apply here to !$entity->getUntranslated()->language()->isLocked()

I want to summarise tstoeckler's probing questions from #7

We have a complex revisionable-cacheable-database-storage mechanism ....

WHERE in a "write-revise-read" test is the data being corrupted?

OR Could it be that whenever the locking status is corrupted then you are bound to get a specific wrong answer?
The wrong answer I am thinking of is the returned empty "array()" from the very first error.

Anyway this is speculation I am not trying to claim I have the definitive answer....just a tantalising possibility.

Regarding #11 and #13 YesCT has blown my arguments out of the water, which is a good thing.

https://www.drupal.org/node/2226533#comment-8942741

I was chasing ghosts

Just keeping this issue apprised of https://www.drupal.org/node/2304651#comment-8977305

looks like YesCT has found stability when it comes to repeating EntityQueryTests.

Found what could be another random fail #2315095: EntityTranslationTest webtest random failure in some patches (not HEAD)
and have not seen this one in a long time.