Change 514038 had a related patch set uploaded (by WMDE-leszek; owner: WMDE-leszek):
[operations/mediawiki-config@master] Do not load InitialiseSettings-labs.php multiple times

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

This task was mentioned in Scrum of scrums/2019-06-05:

Wikidata: Daily browser tests of WikibaseLexeme targetting beta wikidata failing due to odd 500 errors. Some "regular" php fatals discovered on beta cluster, could someone smarter than us have a look: https://phabricator.wikimedia.org/T224899

I'm looking at selenium-daily-beta-WikibaseLexeme Jenkins job but I don't see any 500 errors. Could you please point me to a failure that is caused by a 500 error?

I think I've found it. This?

https://integration.wikimedia.org/ci/job/selenium-daily-beta-WikibaseLexeme/298/artifact/log/ERROR_chrome_2019-06-11T18-05-29.692Z.png

In T224899#5253379, @zeljkofilipin wrote:

This task was mentioned in Scrum of scrums/2019-06-05:

Wikidata: Daily browser tests of WikibaseLexeme targetting beta wikidata failing due to odd 500 errors. Some "regular" php fatals discovered on beta cluster, could someone smarter than us have a look: https://phabricator.wikimedia.org/T224899

I'm looking at selenium-daily-beta-WikibaseLexeme Jenkins job but I don't see any 500 errors. Could you please point me to a failure that is caused by a 500 error?

I had to go back a few days, but the tests for Jun 7 show the error page: https://integration.wikimedia.org/ci/job/selenium-daily-beta-WikibaseLexeme/294/

I expect the others to fail because there the API gets 500 responses. ( Is there a way to monitor the network requests that the page does in Selenium?)

Now that I know what to look for, I've checked the last 10 days, and just one day didn't have a failure connected to a 500 error. 🔥

In T224899#5253379, @zeljkofilipin wrote:

Wikidata: Daily browser tests of WikibaseLexeme targetting beta wikidata failing due to odd 500 errors. Some "regular" php fatals discovered on beta cluster, could someone smarter than us have a look: https://phabricator.wikimedia.org/T224899

How did you make the connection between the screenshot with 500 error and the PHP Fatal error? Using the timestamp from the sceenshot and comparing to errors in https://logstash-beta.wmflabs.org?

So, the problem is that either InitialiseSettings.php or InitialiseSettings-labs.php is sometimes loaded twice? Since, if it was always loaded twice, it would always break, not sometimes? Or, am I misunderstanding this completely?

From https://logstash-beta.wmflabs.org/app/kibana , that notably happens on the jobrunner but also on a wide range of pages.

wmf-config/InitialiseSettings-labs.php is only required from wmf-config/InitialiseSettings.php thus our code somehow requires InitialiseSettings.php twice which is concerning?! Turns out the SiteConfiguration object has a callback that does require InitialiseSettings.php and potentially the error comes from that callback kicking in?

141 # Initialise wgConf
142 require "$wmfConfigDir/wgConf.php";

146 function wmfLoadInitialiseSettings( $conf ) {
147     global $wmfConfigDir;
148     require "$wmfConfigDir/InitialiseSettings.php";   <------------ first require
149 }
150 

193 $globals = false;
194 if ( @filemtime( $filename ) >= filemtime( "$wmfConfigDir/InitialiseSettings.php" ) ) {
195     $cacheRecord = @file_get_contents( $filename );
196     if ( $cacheRecord !== false ) {
197         $globals = unserialize( $cacheRecord );
198     }
199 }   
200 
201 if ( !$globals ) {
202     # Get configuration from SiteConfiguration object
203     require "$wmfConfigDir/InitialiseSettings.php";   <------ second require
204

...
  6 $wgConf = new SiteConfiguration;
...
 24 $dbList = $wmfRealm === 'labs' ? 'all-labs' : 'all';
 25 $wgConf->wikis = MWWikiversions::readDbListFile( $dbList );
 26 
 27 $wgConf->fullLoadCallback = 'wmfLoadInitialiseSettings';

Tldr: someone would need to find a stacktrace or add some debug logging to track InitialiseSettings.php being loaded twice. I would guess the SiteConfiguration callback should not ever be called since the config is supposedly already loaded, but apparently something triggers it

Change 514038 merged by jenkins-bot:
[operations/mediawiki-config@master] Do not load InitialiseSettings-labs.php multiple times

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

Mentioned in SAL (#wikimedia-operations) [2019-07-01T09:13:12Z] <ladsgroup@deploy1001> Synchronized wmf-config/InitialiseSettings.php: [[gerrit:514038|Noop: Do not load InitialiseSettings-labs.php multiple times (T224899)]] (duration: 00m 51s)

Thanks @Ladsgroup for merging the quickfix.

I am not sure if Release-Engineering-Team wouldn't still like to go to the bottom of the issue. As I believe I said https://gerrit.wikimedia.org/r/514038 I believe it was NOT the correct (tm) fix, it just prevents beta site from failing when including the file happens.

In T224899#5256108, @hashar wrote:

Tldr: someone would need to find a stacktrace or add some debug logging to track InitialiseSettings.php being loaded twice. I would guess the SiteConfiguration callback should not ever be called since the config is supposedly already loaded, but apparently something triggers it

What @hashar said still holds, and I believe no one have found the root cause yet.