Page MenuHomePhabricator

mediawiki-phpunit-php70-jessie job sometimes fails with MessageBlobStoreTest failure
Closed, ResolvedPublic

Description

After installing a brand new copy of MW from current head at b347d8e I ran php maintenance/update.php followed by php tests/phpunit/phpunit.php --tap tests/phpunit/includes/resourceloader/MessageBlobStoreTest.php and got the following failure message:

php tests/phpunit/phpunit.php --tap tests/phpunit/includes/resourceloader/MessageBlobStoreTest.php
Using PHP 7.0.22-0ubuntu0.16.04.1
TAP version 13
ok 1 - MessageBlobStoreTest::testSetLogger
ok 2 - MessageBlobStoreTest::testGetResourceLoader
ok 3 - MessageBlobStoreTest::testFetchMessage
ok 4 - MessageBlobStoreTest::testFetchMessageFail
ok 5 - MessageBlobStoreTest::testGetBlob
not ok 6 - Failure: MessageBlobStoreTest::testGetBlobCached
  ---
  message: 'MessageBlobStore::fetchMessage(''example'', ''en'') was not expected to be called.'
  severity: fail
  ...
ok 7 - MessageBlobStoreTest::testUpdateMessage
ok 8 - MessageBlobStoreTest::testValidation
ok 9 - MessageBlobStoreTest::testClear
1..9

This is a brand new installation of MediaWiki with no extensions whatsoever, and with no caching installed (e.g. no memcahced, etc.) so I would expect that test to either pass or be skipped, depending on what is intended behavior.

Notifying @Anomie, @Krinkle and @Legoktm as they seem to have all contributed to pertinent part of the code.

Event Timeline

There are a very large number of changes, so older changes are hidden. Show Older Changes
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptSep 17 2017, 10:37 PM
Huji removed Anomie as the assignee of this task.Sep 17 2017, 10:37 PM

Was assigned by accident. Please feel free to take over or just propose a solution.

Huji added a comment.Sep 18 2017, 2:01 AM

I also sometimes get this one in addition to, or instead of the above:

MessageBlobStoreTest::testClear
Cache-hit
Failed asserting that two strings are equal.
--- Expected
+++ Actual
@@ @@
-'{"example":"First"}'
+'{"example":"Second"}'

/var/www/html/tests/phpunit/includes/resourceloader/MessageBlobStoreTest.php:202
/var/www/html/maintenance/doMaintenance.php:92

The fact that this one and the one above only occur "sometimes" makes me wonder if it has to do with execution speed. I am testing on a VM with 2GB memory and 1 CPU core.

In both cases it seems that the key being fetched from cache is somehow being expired, so the test is finding a cache miss where it expected a hit and so fails. I can't see any reason for that to happen, though.

The MessageBlobStoreTest intentionally doesn't depend on your local installs' cache configuration (which might be CACHE_NONE / EmptyBagOStuff). Instead, the test mocks this in favour of a simple in-memory cache (HashBagOStuff). I don't see how this could end up wiping a key without it explicitly being cleared.

@Huji Do other tests have issues as well, or does it appear specific to MessageBlobStoreTest? Could you try running tests from /tests/phpunit/includes/libs/objectcache, specifically BagOStuffTest, HashBagOStuffTest and WANObjectCacheTest?

Krinkle changed the task status from Open to Stalled.Sep 19 2017, 6:08 PM
Krinkle triaged this task as Medium priority.
Krinkle moved this task from Inbox to Backlog on the MediaWiki-ResourceLoader board.
Krinkle moved this task from Inbox to PHPUnit on the MediaWiki-Core-Testing board.
Huji added a comment.EditedSep 28 2017, 2:58 PM

@Krinkle the only tests that resulted in an error are the ones show above. I cannot reproduce this consistently.

Oh, and /tests/phpunit/includes/libs/objectcache tests all pass successfully

Restricted Application added a project: Performance-Team. · View Herald TranscriptJan 2 2018, 8:17 PM
Huji added a comment.Mar 28 2018, 1:26 AM

This continues to be the case. I just made another fresh installation of MediaWiki using all the default options and ran PHPUnit immediately thereafter, and the output is as follows:

1) MessageBlobStoreTest::testClear
Cache-hit
Failed asserting that two strings are equal.
--- Expected
+++ Actual
@@ @@
-'{"example":"First"}'
+'{"example":"Second"}'

/var/www/html/tests/phpunit/includes/resourceloader/MessageBlobStoreTest.php:204
/var/www/html/maintenance/doMaintenance.php:94

@Huji Please tell me: MediaWiki version, PHP version, and whether any object cache is installed (e.g. APC). The easiest is probably a copy of the install.php output, which answers all these and more. A copy of your generated LocalSettings.php would also help (omit database password and upgrade tokens, if used elsewhere).

Huji added a comment.Mar 28 2018, 2:03 AM
  • MediaWiki version: 1.31.0-alpha (17e8f7d)
  • PHP version: PHP 7.0.28-0ubuntu0.16.04.1 (cli) ( NTS )
  • Object cache: none installed
  • LocalSettings.php file: P6910

@Huji Sorry, but I couldn't reproduce it using php:7.2 (Debian Stretch) nor php:7.0 (Debian Jessie) from https://hub.docker.com/_/php/.

Additionally, https://travis-ci.org/wikimedia/mediawiki/jobs/359640486 shows PHP 7.0 passing as well. And that one uses 7.0.28 and Ubuntu (Trusty). Which should be the same as what you're using.

At this point, I can't really do more unless you're able to reproduce it on a smaller scale. E.g. when running just a subset of the unit tests, as opposed to the entire suite. That would help narrow down what combination of things is causing the failure.

Also, do you have any extensions or skins installed (aside from Vector). If you do, try again with nothing loaded (or just Vector).

Could it be the presence of a cache that is required?

Huji added a comment.Mar 29 2018, 11:22 AM

@Huji Sorry, but I couldn't reproduce it using php:7.2 (Debian Stretch) nor php:7.0 (Debian Jessie) from https://hub.docker.com/_/php/.
Additionally, https://travis-ci.org/wikimedia/mediawiki/jobs/359640486 shows PHP 7.0 passing as well. And that one uses 7.0.28 and Ubuntu (Trusty). Which should be the same as what you're using.
At this point, I can't really do more unless you're able to reproduce it on a smaller scale. E.g. when running just a subset of the unit tests, as opposed to the entire suite. That would help narrow down what combination of things is causing the failure.
Also, do you have any extensions or skins installed (aside from Vector). If you do, try again with nothing loaded (or just Vector).

I don't have anything else installed. I will try to narrow it down to a specific subset of tests, but the MessageBlobStore tests are just flaky (i.e. they past most of the time, but fail some of the time).

Could it be the presence of a cache that is required?

MessageBlobStore uses a mocked WANObjectCache with a HashBagOStuff internally (hash uses plain array in PHP). It does not depend on APC or other cache.

hashar added a subscriber: hashar.Apr 9 2018, 8:27 PM
1) MessageBlobStoreTest::testClear
Cache-hit
Failed asserting that two strings are equal.
--- Expected
+++ Actual
@@ @@
-'{"example":"First"}'
+'{"example":"Second"}'
/var/www/html/tests/phpunit/includes/resourceloader/MessageBlobStoreTest.php:204
/var/www/html/maintenance/doMaintenance.php:94

I got that one on REL1_29 using a Docker container (Stretch, php7) and MariaDB.

hashar added a comment.Apr 9 2018, 8:30 PM

Happened to me while testing an experimental job on https://gerrit.wikimedia.org/r/375798 . The job is mediawiki-core-quibble-composer-mysql-php7-docker

The debug log doesn't have anything interesting though:

[PHPUnitCommand] START suite MessageBlobStoreTest
[PHPUnitCommand] Start test MessageBlobStoreTest::testSetLogger
[PHPUnitCommand] End test MessageBlobStoreTest::testSetLogger
[PHPUnitCommand] Start test MessageBlobStoreTest::testGetResourceLoader
[PHPUnitCommand] End test MessageBlobStoreTest::testGetResourceLoader
[PHPUnitCommand] Start test MessageBlobStoreTest::testFetchMessage
[PHPUnitCommand] End test MessageBlobStoreTest::testFetchMessage
[PHPUnitCommand] Start test MessageBlobStoreTest::testFetchMessageFail
[PHPUnitCommand] End test MessageBlobStoreTest::testFetchMessageFail
[PHPUnitCommand] Start test MessageBlobStoreTest::testGetBlob
[PHPUnitCommand] End test MessageBlobStoreTest::testGetBlob
[PHPUnitCommand] Start test MessageBlobStoreTest::testGetBlobCached
[PHPUnitCommand] End test MessageBlobStoreTest::testGetBlobCached
[PHPUnitCommand] Start test MessageBlobStoreTest::testUpdateMessage
[PHPUnitCommand] End test MessageBlobStoreTest::testUpdateMessage
[PHPUnitCommand] Start test MessageBlobStoreTest::testValidation
[PHPUnitCommand] End test MessageBlobStoreTest::testValidation
[PHPUnitCommand] Start test MessageBlobStoreTest::testClear
[PHPUnitCommand] FAILURE in MessageBlobStoreTest::testClear: [PHPUnit_Framework_ExpectationFailedException] Cache-hit
Failed asserting that two strings are equal.
[PHPUnitCommand] End test MessageBlobStoreTest::testClear
[PHPUnitCommand] END suite MessageBlobStoreTest
hashar added a comment.Apr 9 2018, 8:53 PM

The experimentals jobs in CI have been made against REL1_29 change https://gerrit.wikimedia.org/r/#/c/375798/ . The first show the failure, a second check passed that test.

I have marked the build to be kept forever. Maybe we can dig in the debug/exception logs. But I dont think there will be any difference.

Change 427261 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@master] resourceloader: Disable a flaky MessageBlobStoreTest case

https://gerrit.wikimedia.org/r/427261

Krinkle renamed this task from MessageBlobStoreTest fails on a fresh installation of MediaWiki to mediawiki-phpunit-php70-jessie sometimes fails with MessageBlobStoreTest failure.Apr 17 2018, 9:20 PM
Krinkle renamed this task from mediawiki-phpunit-php70-jessie sometimes fails with MessageBlobStoreTest failure to mediawiki-phpunit-php70-jessie job sometimes fails with MessageBlobStoreTest failure.
Krinkle changed the task status from Stalled to Open.
Krinkle removed a project: MediaWiki-Core-Testing.
Krinkle moved this task from Backlog to Confirmed Problem on the MediaWiki-ResourceLoader board.
Krinkle removed a project: Patch-For-Review.

Seems to also happen on master in the new mediawiki-phpunit-php70-jessie job.

Change 427261 merged by jenkins-bot:
[mediawiki/core@master] resourceloader: Disable a flaky MessageBlobStoreTest case

https://gerrit.wikimedia.org/r/427261

Huji added a comment.Apr 19 2018, 1:10 AM

@Krinkle: I don't get the errors anymore.

@Huji What if you run it with the /** @group Broken */ comment removed from MessageBlobStoreTest.php?

Change 428377 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@REL1_31] resourceloader: Disable a flaky MessageBlobStoreTest case

https://gerrit.wikimedia.org/r/428377

Change 428377 merged by jenkins-bot:
[mediawiki/core@REL1_31] resourceloader: Disable a flaky MessageBlobStoreTest case

https://gerrit.wikimedia.org/r/428377

Krinkle claimed this task.Apr 23 2018, 8:19 PM
Krinkle moved this task from Inbox to Doing on the Performance-Team board.

This job still fails very rarely with an assertion error from testClear(). Both that method and testGetBlobCached deal with caching. Both of them use a HashBagOStuff to store a key and essentially assert that it still exists 1 line later. The Hash cache uses a plain PHP array. It is a mystery to me how a key can disappear there. And I am still unable to reproduce it locally, including with quibble.

Change 436410 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@master] [WIP] resourceloader: Re-enable testGetBlobCached() test case

https://gerrit.wikimedia.org/r/436410

Change 436410 merged by jenkins-bot:
[mediawiki/core@master] resourceloader: Re-enable testGetBlobCached() test case

https://gerrit.wikimedia.org/r/436410

Change 439820 had a related patch set uploaded (by Aaron Schulz; owner: Aaron Schulz):
[mediawiki/core@master] Fix flakey MessageBlobStoreTest assertion failures

https://gerrit.wikimedia.org/r/439820

Krinkle closed this task as Resolved.Jun 14 2018, 11:58 PM

Change 439820 merged by jenkins-bot:
[mediawiki/core@master] Fix flaky MessageBlobStoreTest assertion failures

https://gerrit.wikimedia.org/r/439820

Maybe we can reenable the test in REL1_31 and apply the fix there? It is only for tests though so it is probably not needed.

Change 444368 had a related patch set uploaded (by Reedy; owner: Krinkle):
[mediawiki/core@REL1_30] resourceloader: Disable a flaky MessageBlobStoreTest case

https://gerrit.wikimedia.org/r/444368

Change 444369 had a related patch set uploaded (by Reedy; owner: Krinkle):
[mediawiki/core@REL1_29] resourceloader: Disable a flaky MessageBlobStoreTest case

https://gerrit.wikimedia.org/r/444369

Change 444370 had a related patch set uploaded (by Reedy; owner: Krinkle):
[mediawiki/core@REL1_27] resourceloader: Disable a flaky MessageBlobStoreTest case

https://gerrit.wikimedia.org/r/444370

Change 444368 abandoned by Reedy:
resourceloader: Disable a flaky MessageBlobStoreTest case

https://gerrit.wikimedia.org/r/444368

Change 444369 abandoned by Reedy:
resourceloader: Disable a flaky MessageBlobStoreTest case

https://gerrit.wikimedia.org/r/444369

Change 444370 abandoned by Reedy:
resourceloader: Disable a flaky MessageBlobStoreTest case

https://gerrit.wikimedia.org/r/444370

Change 444373 had a related patch set uploaded (by Reedy; owner: Krinkle):
[mediawiki/core@REL1_31] resourceloader: Re-enable testGetBlobCached() test case

https://gerrit.wikimedia.org/r/444373

Change 444374 had a related patch set uploaded (by Reedy; owner: Aaron Schulz):
[mediawiki/core@REL1_31] Fix flaky MessageBlobStoreTest assertion failures

https://gerrit.wikimedia.org/r/444374

Change 444375 had a related patch set uploaded (by Reedy; owner: Aaron Schulz):
[mediawiki/core@REL1_30] Fix flaky MessageBlobStoreTest assertion failures

https://gerrit.wikimedia.org/r/444375

Change 444376 had a related patch set uploaded (by Reedy; owner: Aaron Schulz):
[mediawiki/core@REL1_29] Fix flaky MessageBlobStoreTest assertion failures

https://gerrit.wikimedia.org/r/444376

Change 444377 had a related patch set uploaded (by Reedy; owner: Aaron Schulz):
[mediawiki/core@REL1_27] Fix flaky MessageBlobStoreTest assertion failures

https://gerrit.wikimedia.org/r/444377

Change 444374 abandoned by Reedy:
Fix flaky MessageBlobStoreTest assertion failures

https://gerrit.wikimedia.org/r/444374

Change 444375 abandoned by Reedy:
Fix flaky MessageBlobStoreTest assertion failures

https://gerrit.wikimedia.org/r/444375

Change 444376 abandoned by Reedy:
Fix flaky MessageBlobStoreTest assertion failures

https://gerrit.wikimedia.org/r/444376

Change 444377 abandoned by Reedy:
Fix flaky MessageBlobStoreTest assertion failures

https://gerrit.wikimedia.org/r/444377

Change 444373 abandoned by Reedy:
resourceloader: Re-enable testGetBlobCached() test case

https://gerrit.wikimedia.org/r/444373

Change 444368 restored by Reedy:
resourceloader: Disable a flaky MessageBlobStoreTest case

https://gerrit.wikimedia.org/r/444368

Change 444369 restored by Reedy:
resourceloader: Disable a flaky MessageBlobStoreTest case

https://gerrit.wikimedia.org/r/444369

Change 444370 restored by Reedy:
resourceloader: Disable a flaky MessageBlobStoreTest case

https://gerrit.wikimedia.org/r/444370

Change 444369 merged by jenkins-bot:
[mediawiki/core@REL1_29] resourceloader: Disable a flaky MessageBlobStoreTest case

https://gerrit.wikimedia.org/r/444369

Change 444368 merged by jenkins-bot:
[mediawiki/core@REL1_30] resourceloader: Disable a flaky MessageBlobStoreTest case

https://gerrit.wikimedia.org/r/444368

Change 444370 merged by jenkins-bot:
[mediawiki/core@REL1_27] resourceloader: Disable a flaky MessageBlobStoreTest case

https://gerrit.wikimedia.org/r/444370

Change 444374 restored by Reedy:
Fix flaky MessageBlobStoreTest assertion failures

https://gerrit.wikimedia.org/r/444374

Change 444374 merged by jenkins-bot:
[mediawiki/core@REL1_31] Fix flaky MessageBlobStoreTest assertion failures

https://gerrit.wikimedia.org/r/444374

mmodell changed the subtype of this task from "Task" to "Production Error".Aug 28 2019, 11:10 PM