Page MenuHomePhabricator

@ and AtEase don't play well together
Closed, ResolvedPublic

Description

I'm writing this task to document the result of an investigation conducted by @Krinkle and me following https://gerrit.wikimedia.org/r/c/mediawiki/core/+/720381, which caused some AbuseFilter tests to fail.

Problem statement

While migrating AtEase calls to the silence operator, some tests could fail with the following message:

PHP error_reporting setting found dirty. Did you forget AtEase::restoreWarnings?

MediaWiki code causing this

Since the failure was not reproducible locally (the first thought was that it could've been caused by one of the gated extensions), this was debugged by pushing debug patches and waiting for CI to test them: test patch 1, test patch 2. Thanks to the debug logging, I eventually narrowed it down to the following code path:

  • Start: error_reporting() == -1, error_reporting INI directive == -1
  • Session::persist()
  • (various calls)
  • Session::checkPHPSession()
  • @session_start()
    • Inside this call, we have error_reporting() == 0 due to the silence operator, INI setting left unchanged at -1
    • The MW session handler (set by session_set_save_handler) is triggered
    • SessionBackend::save()
    • LegacyLogger::debug() --> LegacyLogger::log()
    • LegacyLogger::emit(). This does file operations, so it calls:
      • AtEase::suppressWarnings()
      • AtEase calls error_reporting(), so here we have error_reporting() == 4597, error_reporting INI directive == 4597
      • AtEase::restoreWarnings()
      • The original level is restored, but that was read from error_reporting(), so we now have error_reporting() == 0, error_reporting INI directive == 0
  • The silenced statement ends, which restores error_reporting to -1, but leaves the INI setting at 0
  • End: Start: error_reporting() == -1, error_reporting INI directive == 0
  • There's a mismatch which causes the tests to fail.

Minimal test case

See https://3v4l.org/F19bV. Copied below for convenience:

<?php

class AtEase {
    private static $originalLevel = false;

    static function suppressWarnings() {
    	self::$originalLevel =
			error_reporting( E_ALL & ~(
				E_WARNING |
				E_NOTICE |
				E_USER_WARNING |
				E_USER_NOTICE |
				E_DEPRECATED |
				E_USER_DEPRECATED |
				E_STRICT
			) );
    }
    static function restoreWarnings() {
        error_reporting( self::$originalLevel );
    }
}

function sameAsLoggerDebug() {
    AtEase::suppressWarnings();
    AtEase::restoreWarnings();
}

function sameAsSessionStart() {
    sameAsLoggerDebug();
}

print "PRE er=" . error_reporting() . ' ini=' . intval( ini_get( 'error_reporting' ) ) . "\n";
@sameAsSessionStart();
print "POST er=" . error_reporting() . ' ini=' . intval( ini_get( 'error_reporting' ) ) . "\n";

Results (on PHP < 8):

PRE er=-1 ini=-1
POST er=-1 ini=0

Solution

Quick workaround is to remove all AtEase usage. But it may be hard to predict whether some code ends up using AtEase, since it might happen way further down the chain (as it was the case here). I guess some other workaround might be added to AtEase to make it work correctly here.

Upstream bug report: https://bugs.php.net/bug.php?id=81454

Related Objects

Event Timeline

For future reference, here's a copy of the output of https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-php72-noselenium-docker/108516, which was for both test patches mentioned in the task description applied:

1MediaWiki\Extension\AbuseFilter\Consequences\ConsequencesExecutor::getFilteredConsequences#2 (warn) @1 er=-1 ini=-1
2MediaWiki\Session\SessionBackend::persist@1 () er=-1 ini=-1
3MediaWiki\Logger\LegacyLogger::log@1 er=-1 ini=-1
4MediaWiki\Logger\LegacyLogger::log@4 er=-1 ini=-1
5MediaWiki\Logger\LegacyLogger::log@5 er=-1 ini=-1
6MediaWiki\Logger\LegacyLogger::log@6 er=-1 ini=-1
7MediaWiki\Logger\LegacyLogger::log@7 er=-1 ini=-1
8MediaWiki\Logger\LegacyLogger::log@8 er=-1 ini=-1
9MediaWiki\Logger\LegacyLogger::log@9 er=-1 ini=-1
10MediaWiki\Logger\LegacyLogger::log@10 er=-1 ini=-1
11MediaWiki\Session\SessionBackend::save@1 er=-1 ini=-1
12MediaWiki\Session\SessionBackend::save@2b er=-1 ini=-1
13MediaWiki\Session\SessionBackend::save@5 er=-1 ini=-1
14MediaWiki\Session\SessionBackend::save@6 er=-1 ini=-1
15MediaWiki\Session\SessionBackend::save@6b er=-1 ini=-1
16MediaWiki\Session\SessionBackend::save@6c er=-1 ini=-1
17Session logger:MediaWiki\Logger\LegacyLogger
18MediaWiki\Logger\LegacyLogger::log@1 er=-1 ini=-1
19MediaWiki\Logger\LegacyLogger::log@4 er=-1 ini=-1
20MediaWiki\Logger\LegacyLogger::log@5 er=-1 ini=-1
21MediaWiki\Logger\LegacyLogger::log@6 er=-1 ini=-1
22MediaWiki\Logger\LegacyLogger::log@7 er=-1 ini=-1
23MediaWiki\Logger\LegacyLogger::log@8 er=-1 ini=-1
24MediaWiki\Logger\LegacyLogger::log@9 er=-1 ini=-1
25MediaWiki\Logger\LegacyLogger::log@10 er=-1 ini=-1
26MediaWiki\Session\SessionBackend::save@7 er=-1 ini=-1
27MediaWiki\Session\SessionBackend::save@8 er=-1 ini=-1
28MediaWiki\Session\SessionBackend::save@9 er=-1 ini=-1
29MediaWiki\Logger\LegacyLogger::log@1 er=-1 ini=-1
30MediaWiki\Logger\LegacyLogger::log@4 er=-1 ini=-1
31MediaWiki\Logger\LegacyLogger::log@5 er=-1 ini=-1
32MediaWiki\Logger\LegacyLogger::log@6 er=-1 ini=-1
33MediaWiki\Logger\LegacyLogger::log@7 er=-1 ini=-1
34MediaWiki\Logger\LegacyLogger::log@8 er=-1 ini=-1
35MediaWiki\Logger\LegacyLogger::log@9 er=-1 ini=-1
36MediaWiki\Logger\LegacyLogger::log@10 er=-1 ini=-1
37MediaWiki\Session\SessionBackend::save@10 er=-1 ini=-1
38MediaWiki\Session\SessionBackend::save@11 er=-1 ini=-1
39MediaWiki\Session\SessionBackend::save@12 er=-1 ini=-1
40MediaWiki\Session\SessionBackend::save@12b er=-1 ini=-1
41MediaWiki\Session\SessionBackend::checkPHPSession@1 er=-1 ini=-1
42MediaWiki\Session\SessionBackend::checkPHPSession@2 er=-1 ini=-1
43MediaWiki\Session\SessionBackend::checkPHPSession@3 er=-1 ini=-1
44MediaWiki\Logger\LegacyLogger::log@1 er=-1 ini=-1
45MediaWiki\Logger\LegacyLogger::log@4 er=-1 ini=-1
46MediaWiki\Logger\LegacyLogger::log@5 er=-1 ini=-1
47MediaWiki\Logger\LegacyLogger::log@6 er=-1 ini=-1
48MediaWiki\Logger\LegacyLogger::log@7 er=-1 ini=-1
49MediaWiki\Logger\LegacyLogger::log@8 er=-1 ini=-1
50MediaWiki\Logger\LegacyLogger::log@9 er=-1 ini=-1
51MediaWiki\Logger\LegacyLogger::log@10 er=-1 ini=-1
52MediaWiki\Session\SessionBackend::checkPHPSession@4 er=-1 ini=-1
53MediaWiki\Session\SessionBackend::checkPHPSession@5 er=-1 ini=-1
54MediaWiki\Session\SessionBackend::save@1 er=0 ini=-1
55MediaWiki\Session\SessionBackend::save@2b er=0 ini=-1
56MediaWiki\Session\SessionBackend::save@5 er=0 ini=-1
57MediaWiki\Session\SessionBackend::save@6 er=0 ini=-1
58MediaWiki\Session\SessionBackend::save@6b er=0 ini=-1
59MediaWiki\Session\SessionBackend::save@6c er=0 ini=-1
60Session logger:MediaWiki\Logger\LegacyLogger
61MediaWiki\Logger\LegacyLogger::log@1 er=0 ini=-1
62MediaWiki\Logger\LegacyLogger::log@4 er=0 ini=-1
63MediaWiki\Logger\LegacyLogger::log@5 er=0 ini=-1
64MediaWiki\Logger\LegacyLogger::log@6 er=0 ini=-1
65MediaWiki\Logger\LegacyLogger::log@7 er=0 ini=-1
66MediaWiki\Logger\LegacyLogger::log@8 er=0 ini=0
67MediaWiki\Logger\LegacyLogger::log@9 er=0 ini=0
68MediaWiki\Logger\LegacyLogger::log@10 er=0 ini=0
69MediaWiki\Session\SessionBackend::save@7 er=0 ini=0
70MediaWiki\Session\SessionBackend::save@8 er=0 ini=0
71MediaWiki\Session\SessionBackend::save@9 er=0 ini=0
72MediaWiki\Session\SessionBackend::save@10 er=0 ini=0
73MediaWiki\Session\SessionBackend::save@11 er=0 ini=0
74MediaWiki\Session\SessionBackend::save@8 er=0 ini=0
75MediaWiki\Session\SessionBackend::save@9 er=0 ini=0
76MediaWiki\Session\SessionBackend::save@10 er=0 ini=0
77MediaWiki\Session\SessionBackend::save@11 er=0 ini=0
78MediaWiki\Session\SessionBackend::save@12 er=0 ini=0
79MediaWiki\Session\SessionBackend::save@12b er=0 ini=0
80MediaWiki\Session\SessionBackend::checkPHPSession@1 er=0 ini=0
81MediaWiki\Session\SessionBackend::checkPHPSession@7 er=0 ini=0
82MediaWiki\Session\SessionBackend::save@12c er=0 ini=0
83MediaWiki\Session\SessionBackend::save@17 er=0 ini=0
84MediaWiki\Session\SessionBackend::save@18 er=0 ini=0
85MediaWiki\Session\SessionBackend::save@19 er=0 ini=0
86MediaWiki\Session\SessionBackend::save@20 er=0 ini=0
87MediaWiki\Session\SessionBackend::save@21 er=0 ini=0
88MediaWiki\Session\SessionBackend::save@22 er=0 ini=0
89MediaWiki\Session\SessionBackend::persist@1 (1) er=0 ini=0
90MediaWiki\Session\SessionBackend::save@1 er=0 ini=0
91MediaWiki\Session\SessionBackend::save@2b er=0 ini=0
92MediaWiki\Session\SessionBackend::save@5 er=0 ini=0
93MediaWiki\Session\SessionBackend::save@6 er=0 ini=0
94MediaWiki\Session\SessionBackend::persist@2 er=0 ini=0
95MediaWiki\Session\SessionBackend::checkPHPSession@6 er=-1 ini=0
96MediaWiki\Session\SessionBackend::checkPHPSession@7 er=-1 ini=0
97MediaWiki\Session\SessionBackend::save@12c er=-1 ini=0
98MediaWiki\Session\SessionBackend::save@17 er=-1 ini=0
99MediaWiki\Session\SessionBackend::persist@2 er=-1 ini=0
100MediaWiki\Extension\AbuseFilter\Consequences\Consequence\Warn::shouldBeWarned@1 er=-1 ini=0

Change 721871 had a related patch set uploaded (by Krinkle; author: Krinkle):

[mediawiki/core@master] phpunit: Fix phpErrorFilter check in TestCaseTrait to avoid PHP bug

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

Change 721871 merged by jenkins-bot:

[mediawiki/core@master] phpunit: Fix phpErrorFilter check in TestCaseTrait to avoid PHP bug

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

Krinkle claimed this task.