Page MenuHomePhabricator

PHP Warning "Error while sending QUERY packet. PID" (DatabaseMysqli)
Open, LowPublic

Description

Here's a sample of one of the events in Logstash:

message:  PHP Warning: Error while sending QUERY packet.
host:     snapshot1009
cli_argv: /srv/mediawiki/php-1.32.0-wmf.10/../multiversion/MWScript.php fetchText.php --wiki nlwiki

#0 [internal function]: MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 /srv/mediawiki/php-1.32.0-wmf.10/includes/libs/rdbms/database/DatabaseMysqli.php(46): mysqli->query(string)
#2 /srv/mediawiki/php-1.32.0-wmf.10/includes/libs/rdbms/database/Database.php(1220): Wikimedia\Rdbms\DatabaseMysqli->doQuery(string)
#3 /srv/mediawiki/php-1.32.0-wmf.10/includes/libs/rdbms/database/Database.php(1143): Wikimedia\Rdbms\Database->doProfiledQuery(string, string, boolean, string)
#4 /srv/mediawiki/php-1.32.0-wmf.10/includes/libs/rdbms/database/Database.php(1640): Wikimedia\Rdbms\Database->query(string, string)
#5 /srv/mediawiki/php-1.32.0-wmf.10/includes/libs/rdbms/database/Database.php(1465): Wikimedia\Rdbms\Database->select(string, string, array, string, array, array)
#6 /srv/mediawiki/php-1.32.0-wmf.10/includes/libs/rdbms/database/DBConnRef.php(49): Wikimedia\Rdbms\Database->selectField(string, string, array, string)
#7 /srv/mediawiki/php-1.32.0-wmf.10/includes/libs/rdbms/database/DBConnRef.php(245): Wikimedia\Rdbms\DBConnRef->__call(string, array)
#8 /srv/mediawiki/php-1.32.0-wmf.10/includes/externalstore/ExternalStoreDB.php(209): Wikimedia\Rdbms\DBConnRef->selectField(string, string, array, string)
#9 /srv/mediawiki/php-1.32.0-wmf.10/includes/externalstore/ExternalStoreDB.php(48): ExternalStoreDB->fetchBlob(string, string, boolean)
#10 /srv/mediawiki/php-1.32.0-wmf.10/includes/externalstore/ExternalStore.php(86): ExternalStoreDB->fetchFromURL(string)
#11 /srv/mediawiki/php-1.32.0-wmf.10/includes/Storage/SqlBlobStore.php(407): ExternalStore::fetchFromURL(string, array)
#12 /srv/mediawiki/php-1.32.0-wmf.10/includes/Revision.php(1041): MediaWiki\Storage\SqlBlobStore->expandBlob(string, array, NULL)
#13 /srv/mediawiki/php-1.32.0-wmf.10/maintenance/fetchText.php(86): Revision::getRevisionText(stdClass)
#14 /srv/mediawiki/php-1.32.0-wmf.10/maintenance/fetchText.php(63): FetchText->doGetText(Wikimedia\Rdbms\DatabaseMysqli, integer)
#15 /srv/mediawiki/php-1.32.0-wmf.10/maintenance/doMaintenance.php(94): FetchText->execute()
#16 /srv/mediawiki/php-1.32.0-wmf.10/maintenance/fetchText.php(96): require_once(string)
#17 /srv/mediawiki/multiversion/MWScript.php(100): require_once(string)
#18 {main}

This seems to be happening only on snapshot hosts. Breakdown for past 20 days:

HostCount
snapshot1007538
snapshot1005180
snapshot100988
snapshot100634

Found entries since at least the php-1.32.0-wmf.7 branch.

Maybe related: T193008: MediaWiki\MediaWikiServices::resetChildProcessServices doesn't reset database connection state

Event Timeline

Krinkle created this task.Jul 11 2018, 1:21 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJul 11 2018, 1:21 AM
Krinkle updated the task description. (Show Details)Jul 11 2018, 1:21 AM

Here's a bit more info.

As far as I know, we never saw these on php5 (i.e. May and earlier).

  • These errors only seem to come from fetchText.php or dumptextPass.php, which are called when the full dumps are run, and in particular when historical revision content is dumped. That's once a month.
  • We switched to php7 in mid-May, so the next run dumping historical revision content was June.
  • Logstash doesn't show all the errors that I find in syslog/messages on the hosts; for example there are 18 messages from snapshot1007 on June 11 in logstash, but 21 in the logs on the host. There are messages from June 10 in the logs on the host that are not in logstash at all.
  • fetchText.php doesn't inherit any LB or db stuff; it's a separate process called with proc_open(), and though it occasionally gets respawned by the parent script, those respawns don't correlate with these errrors, so I don't see a connection to T193008; dumpTextPass.php doesn't shuffle its db connection around either unless it's about to respawn fetchText.
  • There's no nice pattern to which wikis have the problem.

Here's a sample from one of the dumpTextPass errors (most of the stack is the same):

message; PHP Warning: Error while sending QUERY packet. PID=10779
host: snapshot1006
cli_argv; /srv/mediawiki/multiversion/MWScript.php dumpTextPass.php --wiki=wikidatawiki --stub=gzip:/mnt/dumpsdata/xmldatadumps/temp/w/wikidatawiki/wikidatawiki-20180601-stub-meta-history22.xml-p23542297p23629459.gz-tmp --prefetch=7zip:/mnt/dumpsdata/xmldatadumps/public/wikidatawiki/20180501/wikidatawiki-20180501-pages-meta-history22.xml-p23474550p23558283.7z;/mnt/dumpsdata/xmldatadumps/public/wikidatawiki/20180501/wikidatawiki-20180501-pages-meta-history22.xml-p23558284p23646958.7z --report=1000 --spawn=/usr/bin/php7.0 --output=bzip2:/mnt/dumpsdata/xmldatadumps/public/wikidatawiki/20180601/wikidatawiki-20180601-pages-meta-history22.xml-p23542297p23629459.bz2.inprog --full

#0 [internal function]: MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 /srv/mediawiki/php-1.32.0-wmf.7/includes/libs/rdbms/database/DatabaseMysqli.php(46): mysqli->query(string)
#2 /srv/mediawiki/php-1.32.0-wmf.7/includes/libs/rdbms/database/Database.php(1220): Wikimedia\Rdbms\DatabaseMysqli->doQuery(string)
#3 /srv/mediawiki/php-1.32.0-wmf.7/includes/libs/rdbms/database/Database.php(1143): Wikimedia\Rdbms\Database->doProfiledQuery(string, string, boolean, string)
#4 /srv/mediawiki/php-1.32.0-wmf.7/includes/libs/rdbms/database/Database.php(1640): Wikimedia\Rdbms\Database->query(string, string)
#5 /srv/mediawiki/php-1.32.0-wmf.7/includes/libs/rdbms/database/Database.php(1465): Wikimedia\Rdbms\Database->select(string, string, array, string, array, array)
#6 /srv/mediawiki/php-1.32.0-wmf.7/maintenance/dumpTextPass.php(645): Wikimedia\Rdbms\Database->selectField(string, string, array)
#7 /srv/mediawiki/php-1.32.0-wmf.7/maintenance/dumpTextPass.php(888): TextPassDumper->getText(string, string, string)
#8 [internal function]: TextPassDumper->startElement(resource, string, array)
#9 /srv/mediawiki/php-1.32.0-wmf.7/maintenance/dumpTextPass.php(448): xml_parse(resource, string, boolean)
#10 /srv/mediawiki/php-1.32.0-wmf.7/maintenance/dumpTextPass.php(274): TextPassDumper->readDump(resource)
#11 /srv/mediawiki/php-1.32.0-wmf.7/maintenance/dumpTextPass.php(143): TextPassDumper->dump(boolean)
#12 /srv/mediawiki/php-1.32.0-wmf.7/maintenance/doMaintenance.php(94): TextPassDumper->execute()
#13 /srv/mediawiki/php-1.32.0-wmf.7/maintenance/dumpTextPass.php(992): require_once(string)
#14 /srv/mediawiki/multiversion/MWScript.php(100): require_once(string)
#15 {main}

I dug around in the php source and MW source looking for obscure reasons the packet send might return an error but turned up nothing.
Enabling debug-level logging isn't really feasible, as this error happens for only a few requests out of tens of thousands (or more).

@ArielGlenn What is the current impact of this? Does the script recover from the problem?

Yes, it keeps chugging right along. I would never have noticed these errors if you hadn't pointed them out, tbh.

Krinkle triaged this task as Low priority.Jul 16 2018, 9:54 PM
Krinkle moved this task from Untriaged to Meta on the Wikimedia-production-error board.

Thanks. Still worth figuring out at some point, but I'll move it into low impact for now.

hashar added a subscriber: hashar.Sep 5 2018, 1:02 PM

Various reports seems to indicate MariaDB setting max_allowed_packet_size should be bumped. Most probably the query statement is just too large and we should make the query smaller? It would probably help to catch the exception and log the actual query. Maybe DBA can help? They might have errors log on the database side.

I thought we were capped at 2048k for revision text, so how would we exceed that 32M packet size? But you're right, it would be nice to log the query somehow.