Page MenuHomePhabricator

MWDebugTest::testAppendDebugInfoToApiResultXmlFormat fails when enabling $wgDebug vars
Open, HighPublic

Description

https://travis-ci.org/wikimedia/mediawiki/jobs/342150461

There was 1 error:
1) MWDebugTest::testAppendDebugInfoToApiResultXmlFormat
PHPUnit_Framework_Exception: Argument #2 (No Value) of PHPUnit_Framework_Assert::assertArrayHasKey() must be a array or ArrayAccess
/home/travis/build/wikimedia/mediawiki/tests/phpunit/includes/debug/MWDebugTest.php:110
/home/travis/build/wikimedia/mediawiki/tests/phpunit/MediaWikiTestCase.php:420
/home/travis/build/wikimedia/mediawiki/maintenance/doMaintenance.php:94

See also:

  • T182368 (same test failing, but due to a different error)

It seems this only happens when enabling these three configuration variables, per https://gerrit.wikimedia.org/r/#/c/412830/6/includes/DevelopmentSettings.php

// Enable verbose logging
$wgDebugComments = true;
$wgDebugDumpSql = true;
$wgDebugTimestamps = true;

It seems that enabling any one or two of these, does not make the tests fail, only all three.

Event Timeline

Krinkle created this task.Feb 16 2018, 8:20 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptFeb 16 2018, 8:20 PM
Krinkle updated the task description. (Show Details)Feb 16 2018, 8:20 PM
Krinkle triaged this task as High priority.
Krinkle moved this task from Inbox to PHPUnit on the MediaWiki-Core-Testing board.
Krinkle moved this task from Unsorted to PHP 7.1 on the [DO NOT USE] NewPHP board.
Krinkle renamed this task from MWDebugTest::testAppendDebugInfoToApiResultXmlFormat failing on PHP 7.1 to MWDebugTest::testAppendDebugInfoToApiResultXmlFormat failing on PHP 7.0 and 7.1 (assertArrayHasKey).
Krinkle moved this task from PHP 7.1 to PHP 7 on the [DO NOT USE] NewPHP board.Feb 16 2018, 10:42 PM

This test has nothing to do with the API.

I can't reproduce this locally. It looks like you've got some other serious weirdness going on in that log too.

This has started happening in Wikimedia CI, for example on https://gerrit.wikimedia.org/r/#/c/412653/:

https://integration.wikimedia.org/ci/job/mediawiki-phpunit-hhvm-jessie/19594/console

09:02:36 There was 1 error:
09:02:36 
09:02:36 1) MWDebugTest::testAppendDebugInfoToApiResultXmlFormat
09:02:36 PHPUnit_Framework_Exception: Argument #2 (No Value) of PHPUnit_Framework_Assert::assertArrayHasKey() must be a array or ArrayAccess
09:02:36 
09:02:36 /home/jenkins/workspace/mediawiki-phpunit-hhvm-jessie/src/tests/phpunit/includes/debug/MWDebugTest.php:110
09:02:36 /home/jenkins/workspace/mediawiki-phpunit-hhvm-jessie/src/tests/phpunit/MediaWikiTestCase.php:420
09:02:36 /home/jenkins/workspace/mediawiki-phpunit-hhvm-jessie/src/maintenance/doMaintenance.php:94

I tried to put a var_dump() there (https://gerrit.wikimedia.org/r/#/c/412749/) and $data at this point is just array(1) { ["_type"] => string(5) "assoc" }.

My unverified hunch is that this is related to the DevelopmentSettings.php change by @Krinkle.

I also wondered why the core has not been updated recently, it seems that jenkins-bot has block there patches.

Hm.. that shouldn't affect the unit tests in any way. Even less for our CI than for Travis. For our CI, it effectively just moved settings from being loaded via LocalSettings from integration/jenkins, to... being loaded via LocalSettings from integration/jenkins from mediawiki/core. The same settings were moved as-is to core and are still included at the some point of the loading sequence.

Well once I reverted that change, it started passing again. So I'm fairly sure it's that.

Legoktm renamed this task from MWDebugTest::testAppendDebugInfoToApiResultXmlFormat failing on PHP 7.0 and 7.1 (assertArrayHasKey) to MWDebugTest::testAppendDebugInfoToApiResultXmlFormat failing when using DevelopmentSettings.php.Feb 19 2018, 10:05 PM

The only difference between the two implementations of dev settings are these lines, which were added to DevelopmentSettings.php after the initial import from integration/jenkins.git

+ // Enable verbose logging
+ $wgDebugComments = true;
+ $wgDebugDumpSql = true;
+ $wgDebugTimestamps = true;
+ 

I'll try removing these in core to see if it makes the Travis CI job pass, and if so, I'll re-apply the enabling of DevelopmentSettings.php in integration/jenkins.php. Then, once that's in place, we can add these back in unmerged gerrit change sets to see which one makes the build fail.

Krinkle claimed this task.Feb 19 2018, 10:16 PM

Change 412823 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@master] tests: Remove verbose logging settings from DevelopmentSettings.php

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

Change 412823 merged by jenkins-bot:
[mediawiki/core@master] tests: Remove verbose logging settings from DevelopmentSettings.php

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

Change 412823 merged by jenkins-bot:
[mediawiki/core@master] tests: Remove verbose logging settings from DevelopmentSettings.php

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

Remaining failures are specific to Postgres and PHP 7.1+, and not new.

Change 412825 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[integration/jenkins@master] mwconf: Re-enable use of built-in DevelopmentSettings.php

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

I'll try removing these in core to see if it makes the Travis CI job pass, and if so, I'll re-apply the enabling of DevelopmentSettings.php in integration/jenkins.php. Then, once that's in place, we can add these back in unmerged gerrit change sets to see which one makes the build fail.

Sounds good to me. I'd also like us to regenerate the nodepool images immediately so we can see if it fails right away instead of waiting for nodepool to do its nightly refresh.

Change 412825 merged by jenkins-bot:
[integration/jenkins@master] mwconf: Re-enable use of built-in DevelopmentSettings.php

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

Change 412830 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@master] [WIP] tests: Debugging T187581

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

I might see what's going on here. It goes along with the "serious weirdness" I mentioned earlier: something about one of those configuration settings is making it dump tons of debug logs into the output HTML. If it's trying to put that same tons of debug logs into the ApiResult, the $result->addValue() call in there is going to fail due to exceeding the ApiResult size limits. Thus that 'debuginfo' key never gets added.

That could also explain my being unable to reproduce it: if that tons of debug logging is built up over all the tests that run previously, it wouldn't be built up when I run just the MWDebug tests.

@Anomie Can we adapt the test to not absorb this global state? E.g. by mocking or disabling those debug logs for the purpose of this unit test?

Since it's all static functions, mocking probably won't work too well. You could use TestingAccessWrapper to fix its internal variables.

But where is it being enabled in the first place? The one place it's enabled outside of tests seems like it shouldn't be triggered, and I'd hope PHPUnit's setUpBeforeClass isn't really "setupBeforeAllClasses".

Krinkle removed Krinkle as the assignee of this task.Feb 21 2018, 7:55 PM
Krinkle renamed this task from MWDebugTest::testAppendDebugInfoToApiResultXmlFormat failing when using DevelopmentSettings.php to MWDebugTest::testAppendDebugInfoToApiResultXmlFormat fails when enabling $wgDebug vars.
Krinkle updated the task description. (Show Details)

Change 412830 abandoned by Krinkle:
[WIP] tests: Debugging T187581

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

matmarex removed a subscriber: matmarex.Feb 28 2018, 2:09 AM

I concur with @Anomie on the cause.

I reproduced the error locally by enabling the debugging variables from the description, and temporarily adding this evil little piece of code at the top of testAppendDebugInfoToApiResultXmlFormat:

		for ( $i = 0; $i < 1000000; $i++ ) {
			LoggerFactory::getInstance( 'bdp' )->debug( $i );
		}

In my first attempt, I had the loop counter at 1000, and the error did not appear. I kept increasing it by 10x, and eventually the error occurred.

Do we still feel this is related to PHP 7, or can we remove that tag from this task?

Do we still feel this is related to PHP 7, or can we remove that tag from this task?

Removed. Above in the comments there are failures on HHVM as well.