In T145819#2642193, @Addshore wrote:

2016-09-15 19:59:54 [139a37a9f227e562aefeee8d] terbium wikidatawiki 1.28.0-wmf.19 exception ERROR: [139a37a9f227e562aefeee8d] [no req]   MWException from line 561 of /srv/mediawiki/php-1.28.0-wmf.19/includes/SiteConfiguration.php: Failed to run getConfiguration.php. {"exception_id":"139a37a9f227e562aefeee8d"}

Maybe T145839 is related:

[V9vCrwpEFhUAADfGIToAAAAC] /wiki/Special:CreateAccount MWException from line 561 of /srv/mediawiki/php-master/includes/SiteConfiguration.php: Failed to run getConfiguration.php.
...

And strace is again my friend. Running it with:

• -y to show file descriptor names
• -e trace=desc for system calls related to file descriptor
• -s 2048 for large strings

[pid 25957] open("/var/cache/hhvm/cli.hhbc.sq3", O_RDWR|O_CREAT|O_CLOEXEC, 0644) = 7
[pid 25957] open("/var/cache/hhvm/cli.hhbc.sq3-journal", O_RDWR|O_CLOEXEC) = 8

That is sqlite journaling.

[pid 25957] read(8</var/cache/hhvm/cli.hhbc.sq3-journal>, ..., 1024 ) = 1024
[pid 25957] lseek(7</var/cache/hhvm/cli.hhbc.sq3>, 844421120, SEEK_SET) = 844421120
[pid 25957] write(7</var/cache/hhvm/cli.hhbc.sq3>, ... , 1024 ) = -1 EFBIG (File too large)
[pid 25957] --- SIGXFSZ {si_signo=SIGXFSZ, si_code=SI_USER, si_pid=25957, si_uid=33} ---

[pid 25957] +++ killed by SIGXFSZ (core dumped) +++
[pid 25954] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_DUMPED, si_pid=25957, si_status=SIGXFSZ, si_utime=3, si_stime=22} ---

Command for copy pasting:
sudo -u www-data strace -y -e trace=desc -s2048 -f /bin/bash /srv/mediawiki/php-1.28.0-wmf.19/includes/limit.sh '/usr/bin/php /srv/mediawiki/multiversion/MWScript.php maintenance/getConfiguration.php --wiki dewikinews --settings wgJobClasses --format PHP' 'MW_INCLUDE_STDERR=;MW_CPU_LIMIT=50;MW_CGROUP=/sys/fs/cgroup/memory/mediawiki/job; MW_MEM_LIMIT=0; MW_FILE_SIZE_LIMIT=524288; MW_WALL_CLOCK_LIMIT=180'; echo "Exit code: $?"

Without strace but with MW_INCLUDE_STDERR=1

/srv/mediawiki/php-1.28.0-wmf.19/includes/limit.sh: line 101: 24089 File size limit exceeded/usr/bin/timeout $MW_WALL_CLOCK_LIMIT /bin/bash -c "$1" 3>&-

TLDR: when running mwscript on terbium the HHVM cache file /var/cache/hhvm/cli.hhbc.sq3 is committed to. Sqlite3 then use the journaling system to rewrite it and that explodes due to the ulimit -f.

SiteConfiguration::getConfig() uses wfShellWikiCmd() to craft the command it uses the PHP interpreter from $wgPhpCli, that is '/usr/bin/php' which on terbium is hhvm.

549             $retVal = 1;
550             $cmd = wfShellWikiCmd(
551                 "$IP/maintenance/getConfiguration.php",
552                 [
553                     '--wiki', $wiki,
554                     '--settings', implode( ' ', $settings ),
555                     '--format', 'PHP'
556                 ]
557             );

Then the call is made. Note the comment about ulimit5.sh breaking the call !!! The memory limit is set to zero explicitly :(

558             // ulimit5.sh breaks this call
559             $data = trim( wfShellExec( $cmd, $retVal, [], [ 'memory' => 0 ] ) );
560             if ( $retVal != 0 || !strlen( $data ) ) {
561                 throw new MWException( "Failed to run getConfiguration.php." );
562             }
563             $res = unserialize( $data );
564             if ( !is_array( $res ) ) {
565                 throw new MWException( "Failed to unserialize configuration array." );
566             }
567             $this->cfgCache[$wiki] = $this->cfgCache[$wiki] + $res;

A monkey patch would be to pass to wfShellExec the env 'filesize' => 0 to workaround the write to the HHVM cache file.

Unsolved

Why on 1.28.0.wmf-18 /var/cache/hhvm/cli.hhbc.sq3 is not updated/written to but it is on 1.28.0.wmf-19.

On the Beta-Cluster-Infrastructure

Trying with the ulimit at 512k

sudo -u www-data /bin/bash /srv/mediawiki/php-master/includes/limit.sh '/usr/bin/php /srv/mediawiki/multiversion/MWScript.php maintenance/getConfiguration.php --wiki wikidatawiki --settings wgJobClasses --format PHP' 'MW_INCLUDE_STDERR=;MW_CPU_LIMIT=50;MW_CGROUP=/sys/fs/cgroup/memory/mediawiki/job; MW_MEM_LIMIT=0; MW_FILE_SIZE_LIMIT=524288; MW_WALL_CLOCK_LIMIT=180;'; echo "Exit code: $?"

OK deployment-mediawiki05, Jessie, HHVM 3.12.7+dfsg-1+wmf1
OK deployment-tin, Trusty, HHVM 3.12.1+dfsg-1~wmf2+trusty0

Upgraded HHVM on deployment-tin to 3.12.7+dfsg-1+wmf1~trusty1. It still write to the journal file and run fine.

I am trying in production now :(

OK mw1273, Jessie, 3.12.7+dfsg-1+wmf1

BAD terbium, Trusty, 3.12.7+dfsg-1+wmf1~trusty1

Running:

sudo -u www-data /bin/bash /srv/mediawiki/php-1.28.0-wmf.19/includes/limit.sh '/usr/bin/php /srv/mediawiki/multiversion/MWScript.php maintenance/getConfiguration.php --wiki dewikinews --settings wgJobClasses --format PHP' 'MW_INCLUDE_STDERR=;MW_CPU_LIMIT=50;MW_CGROUP=/sys/fs/cgroup/memory/mediawiki/job; MW_MEM_LIMIT=0; MW_FILE_SIZE_LIMIT=524288; MW_WALL_CLOCK_LIMIT=180'; echo "Exit code: $?"

WORKS on tin
FAIL on terbium

On terbium I then delete /var/cache/hhvm/cli.hhbc.sq3 and the command now pass.

On terbium cli.hhbc.sq3 was 876 MBytes. It is now down to 17 MBytes.

Change 311118 had a related patch set uploaded (by Hashar):
Inline doc for $wgMaxShell*

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

Got a Failed to run getConfiguration.php. on mw1215.eqiad.wmnet:

$ ls -hl /var/cache/hhvm/
total 2.5G
-rw-r--r-- 1 www-data www-data 202M Sep 16 12:28 cli.hhbc.sq3
-rw-r--r-- 1 www-data www-data 2.3G Sep 16 04:10 fcgi.hhbc.sq3

That is from an api.php call. If the file limit stands true, cli.hhbc.sq3 is only 202Mbytes so I am not sure why that fails.

Mentioned in SAL (#wikimedia-operations) [2016-09-16T12:40:02Z] <hashar> Going to rollback all Wikis back to 1.28.0-wmf.18 . Despite much investigation, a bunch of jobs are broken due to T145819 which includes Special:CreateAccount :(

Change 311120 had a related patch set uploaded (by Hashar):
All wikis back to 1.28.0-wmf.18

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

Change 311120 merged by jenkins-bot:
All wikis back to 1.28.0-wmf.18

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

Mentioned in SAL (#wikimedia-operations) [2016-09-16T12:50:09Z] <hashar@tin> rebuilt wikiversions.php and synchronized wikiversions files: All wikis back to 1.28.0-wmf.18 :( T145819

From T145839#2643508 (task about Special:CreateAccount broken:

Sorry I took time to notice this bug was about Special:CreateAccount being broken. I though it was just yet a random job failling due to T145819. So I kept investigating that other task.

Eventually I have browsed the dashboard for authentication metrics at https://grafana.wikimedia.org/dashboard/db/authentication-metrics?panelId=14&fullscreen Screenshot of the last 24 hours shows a 100% error rate on account creation:

I have reverted all wikis to 1.28.0-wmf.18 as a result which is reflected in the drop of errors at the far right of the graph above.

Sorry, should really have noticed that earlier.

All wikis are now back to 1.28.0-wmf.18. The Wikidata dispatch lag is all fine Account creation jobs are back as well.

I am enlarging the scope of this task. It is not just Wikidata but more about a variety of jobs that fails whenever shelling out to mwscript maintenance/getConfiguration.php.

Incident report is at https://wikitech.wikimedia.org/wiki/Incident_documentation/20160915-MediaWiki

(Huge thanks to @Addshore for the support/pointers etc)

It looks like rMW6f9a246d25b2: Make JobQueueGroup::push() update the queuesHaveJobs() cache is what made job pushing start triggering T111441. It'll affect any code that pushes a job onto another wiki's job queue. @aaron might know if we could revert that patch until T111441 can be fixed, or if we can adjust the added code to only run if the job is being pushed on the local wiki.

Change 311168 had a related patch set uploaded (by Aaron Schulz):
Avoid triggering SiteConfiguration lookup in JobQueueGroup::push()

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

Change 311172 had a related patch set uploaded (by Aaron Schulz):
Avoid triggering SiteConfiguration lookup in JobQueueGroup::push()

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

Change 311172 merged by jenkins-bot:
Avoid triggering SiteConfiguration lookup in JobQueueGroup::push()

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

Change 311168 merged by jenkins-bot:
Avoid triggering SiteConfiguration lookup in JobQueueGroup::push()

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

Change 311118 merged by jenkins-bot:
Inline doc for $wgMaxShell*

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

A view of messages referencing /srv/mediawiki/php-1.28.0-wmf.19/includes/SiteConfiguration.php as referenced by @Addshore previously in https://logstash.wikimedia.org/goto/259821dc32242eb3fde0cd02755685f6

Fields:

• server: name of the server. codfw / snapshot hosts have been removed (had 0 errors)
• n_err number of lines in logstash
• cli_size human readable size of /var/cache/hhvm/cli.hhvm.sq3
• cli_date date of file as reported by ls
• fcgi_size/fcgi_date same but for /var/cache/hhvm/fcgi.hhvm.sq3

I have starred has that table for a while. Cant find anything specific of interest but maybe someone else will?

Seems like the cgi cache files have been trashed/regenerated on some hosts.

There seems to be a larger underlying issue (captured in T111441).

Since @aaron and @Anomie merged and back-ported https://gerrit.wikimedia.org/r/311172, is that sufficient to try wmf.19 again this Tuesday? Or should T111441 block the train until it is resolved?

It should be noted, as it may factor in to the decision, that there will be no train next week (2016-09-26) since ops will be at an offsite.

The backport should get the maintenance script call rate back to the old status quo (rare), so re-deploy is worth attempting.

T111441 is most probably a beast too large to get rid of in a short time, and I don't even know who could be diverted to work on it.

I would at least clear out the HHVM bytecode caches for to be safe. A server that failed had a 202MBytes file:

In T145819#2643463, @hashar wrote:

Got a Failed to run getConfiguration.php. on mw1215.eqiad.wmnet:

$ ls -hl /var/cache/hhvm/
total 2.5G
-rw-r--r-- 1 www-data www-data 202M Sep 16 12:28 cli.hhbc.sq3
-rw-r--r-- 1 www-data www-data 2.3G Sep 16 04:10 fcgi.hhbc.sq3

That is from an api.php call. If the file limit stands true, cli.hhbc.sq3 is only 202Mbytes so I am not sure why that fails.

The table above is for today and show a lot of servers are around that size if not bigger, thus I highly suspect that will trigger the ulimit again.

Ideally, it would nice to figure out why the bytecode cache has to be written to. My assumption is that we should get it compiled once on each deploy, and mwscript would not have to mess with it.

When proceeding with the deployment, I highly recommend to do the jobrunners one at a time. Watch logstash for it. Note that /var/log/mediawiki/jobrunner.log is only readable by root for now (due to T146040)

In T145819#2649573, @aaron wrote:

The backport should get the maintenance script call rate back to the old status quo (rare), so re-deploy is worth attempting.

Trying the redeploy now.

wmf.19 is on group0 wikis currently.

Plan is to move group1 at 21:45, and all wikis at 22:00 if there is nothing suspicious in the error logs and no reports of any breakage.

We're back to wmf.18 now.

In T145819#2650834, @greg wrote:

We're back to wmf.18 now.

explanation on the wmf.19 blockers task T143328#2651001 the rollback was not due to the problems outlined in this task; although, I was not able to confirm that this task was resolved.

T145839: Account creation results in fatal MWException was duplicated into this task, and this is still open, so I am confused. Account creation is no longer broken, right?

In T145819#2663000, @matmarex wrote:

T145839: Account creation results in fatal MWException was duplicated into this task, and this is still open, so I am confused. Account creation is no longer broken, right?

Account creation is no longer broke, correct.

What are the next steps here, @thcipriani (on duty train conductor, even though we don't have a train this week), @hashar (was on duty for this issue), and @aaron (person who wrote some patches to address at least parts of this)?

It should be a goal to replace usage of the maintenance config script, but not high priority IMO.

Might be surfacing again from CirrusSearch related web requests (that shell out to mwscript getConfig): T161520

Dealing with the HHVM byte code cache is being forked as sub task T161598

That is still surfacing here and there from time to time.

Maybe we can have Scap to prime the CLI byte code cache ( /var/cache/hhvm/cli.hhbc.sq3 ). This way when HHVM is run in CLI it would not trigger the cache update (and thus reaching the ulimit).

Another way is to have Scap to delete /var/cache/hhvm/cli.hhbc.sq3 on deployment?

Change 391170 had a related patch set uploaded (by Tim Starling; owner: Tim Starling):
[mediawiki/core@master] Do not limit filesize when running a maintenance script

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

Change 391170 merged by jenkins-bot:
[mediawiki/core@master] Do not limit filesize when running a maintenance script

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