Page MenuHomePhabricator
Create Task
Maniphest T201900

PHP Notice: Trying to get property 'num_rows' of non-object in /home/travis/build/wikimedia/mediawiki/includes/libs/rdbms/database/DatabaseMysqli.php on line 233 on PHP 7.2 travis builds
Closed, ResolvedPublicPRODUCTION ERROR
Actions

Description

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

PHP Notice:  Trying to get property 'num_rows' of non-object in /home/travis/build/wikimedia/mediawiki/includes/libs/rdbms/database/DatabaseMysqli.php on line 233
PHP Stack trace:
PHP   1. {main}() /home/travis/build/wikimedia/mediawiki/tests/phpunit/phpunit.php:0
PHP   2. require() /home/travis/build/wikimedia/mediawiki/tests/phpunit/phpunit.php:174
PHP   3. PHPUnitMaintClass->execute() /home/travis/build/wikimedia/mediawiki/maintenance/doMaintenance.php:94
PHP   4. PHPUnit\TextUI\Command::main() /home/travis/build/wikimedia/mediawiki/tests/phpunit/phpunit.php:135
PHP   5. PHPUnit\TextUI\Command->run() /home/travis/build/wikimedia/mediawiki/vendor/phpunit/phpunit/src/TextUI/Command.php:148
PHP   6. PHPUnit\TextUI\TestRunner->doRun() /home/travis/build/wikimedia/mediawiki/vendor/phpunit/phpunit/src/TextUI/Command.php:195
PHP   7. PHPUnit\Framework\TestSuite->run() /home/travis/build/wikimedia/mediawiki/vendor/phpunit/phpunit/src/TextUI/TestRunner.php:546
PHP   8. PHPUnit\Framework\TestSuite->run() /home/travis/build/wikimedia/mediawiki/vendor/phpunit/phpunit/src/Framework/TestSuite.php:755
PHP   9. PHPUnit\Framework\TestSuite->run() /home/travis/build/wikimedia/mediawiki/vendor/phpunit/phpunit/src/Framework/TestSuite.php:755
PHP  10. MediaWiki\Session\SessionInfoTest->run() /home/travis/build/wikimedia/mediawiki/vendor/phpunit/phpunit/src/Framework/TestSuite.php:755
PHP  11. MediaWiki\Session\SessionInfoTest->setUpSchema() /home/travis/build/wikimedia/mediawiki/tests/phpunit/MediaWikiTestCase.php:466
PHP  12. MediaWiki\Session\SessionInfoTest->undoSchemaOverrides() /home/travis/build/wikimedia/mediawiki/tests/phpunit/MediaWikiTestCase.php:1593
PHP  13. MediaWiki\Session\SessionInfoTest->recloneMockTables() /home/travis/build/wikimedia/mediawiki/tests/phpunit/MediaWikiTestCase.php:1579
PHP  14. CloneDatabase->cloneTableStructure() /home/travis/build/wikimedia/mediawiki/tests/phpunit/MediaWikiTestCase.php:1722
PHP  15. Wikimedia\Rdbms\DatabaseMysqli->duplicateTableStructure() /home/travis/build/wikimedia/mediawiki/includes/db/CloneDatabase.php:109
PHP  16. Wikimedia\Rdbms\DatabaseMysqli->query() /home/travis/build/wikimedia/mediawiki/includes/libs/rdbms/database/DatabaseMysqlBase.php:1454
PHP  17. Wikimedia\Rdbms\DatabaseMysqli->doProfiledQuery() /home/travis/build/wikimedia/mediawiki/includes/libs/rdbms/database/Database.php:1143
PHP  18. Wikimedia\Rdbms\DatabaseMysqli->numRows() /home/travis/build/wikimedia/mediawiki/includes/libs/rdbms/database/Database.php:1245
PHP  19. Wikimedia\Rdbms\DatabaseMysqli->mysqlNumRows() /home/travis/build/wikimedia/mediawiki/includes/libs/rdbms/database/DatabaseMysqlBase.php:370

I don't really understand how this notice is possible at all because this function is very clearly wrapped in suppressWarnings/restoreWarnings.

Details

Related Changes in Gerrit:
SubjectRepoBranchLines +/-
Database result type is mostly opaque to our classesmediawiki/coremaster+30 -25
Guard numRows, not appropriate for some queriesmediawiki/coremaster+111 -10
Fix guarding of MySQL's numRows()mediawiki/corewmf/1.32.0-wmf.24+3 -2
Fix guarding of MySQL's numRows()mediawiki/coremaster+3 -2
rdbms: Document a bunch of stuff about query verbsmediawiki/coremaster+30 -4
rdbms: Avoid numRows() warnings for mysqli after table creationmediawiki/coremaster+1 -1
Customize query in gerrit

Related Objects

Event Timeline

Legoktm created this task.Aug 14 2018, 8:20 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptAug 14 2018, 8:20 AM
Umherirrender added subscribers: aaron, Umherirrender.Aug 14 2018, 5:40 PM

It seems mysqli_result->num_rows is not set for CREATE statement (or other DDL)

No idea why suppression is not working

The new call of numRows is possible coming from https://gerrit.wikimedia.org/r/#/c/mediawiki/core/+/443405/

gerritbot subscribed.Aug 14 2018, 6:42 PM

Change 452733 had a related patch set uploaded (by Aaron Schulz; owner: Aaron Schulz):
[mediawiki/core@master] Avoid numRows() warnings for mysqli after table creation

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

gerritbot added a project: Patch-For-Review.Aug 14 2018, 6:42 PM
Krinkle moved this task from Untriaged to Rdbms library on the MediaWiki-libs-Rdbms board.Aug 14 2018, 6:49 PM
gerritbot added a comment.Aug 14 2018, 8:24 PM

Change 452733 merged by jenkins-bot:
[mediawiki/core@master] rdbms: Avoid numRows() warnings for mysqli after table creation

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

ReleaseTaggerBot added a project: MW-1.32-notes (WMF-deploy-2018-08-21 (1.32.0-wmf.18)).Aug 14 2018, 9:00 PM
Krinkle closed this task as Resolved.Aug 14 2018, 9:39 PM
Krinkle assigned this task to aaron.
Krinkle moved this task from Untriaged to Resolved on the Wikimedia-production-error (ARCHIVED -- Shared Build Failure) board.
Krinkle mentioned this in T201776: TitlePermissionTest failing on travis-ci after ContentLanguage service conversion .
Krinkle edited projects, added Performance-Team; removed Patch-For-Review.Aug 14 2018, 10:09 PM
RazeSoldier reopened this task as Open.Sep 20 2018, 2:51 PM
RazeSoldier subscribed.

The PHP Notice still show in travis-CI and caused the log to exceed the maximum log length, causing the job process to be terminated.

Reedy subscribed.Sep 20 2018, 10:52 PM

Yeah, there's definitely a load of them...

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

Krinkle merged a task: T202806: Confirm DatabaseMysqlBase::numRows error suppression works as intended (non-object in DatabaseMysqli::mysqlNumRows).Sep 21 2018, 3:48 PM
Krinkle added a subscriber: Tgr.
Tgr added a comment.Sep 21 2018, 5:31 PM
In T201900#4502405, @Umherirrender wrote:

No idea why suppression is not working

Maybe due to the return value of MWExceptionHandler::handleError() ignoring error reporting levels? The logging code does take them into account and does not write to the error log, but the return value determines whether PHP invokes the default error handler (which prints to stdout).

OTOH notices don't normally come with stack traces so that's probably not what's happening.

Krinkle added a comment.Sep 23 2018, 4:26 AM

OTOH notices don't normally come with stack traces so that's probably not what's happening.

MediaWiki's own error handler creates traces, but as far as I know, we only print those to Monolog, not to standard out. So it's probably not ours indeed.

MediaWiki does configure PHPUnit to convert errors to exceptions. And when PHPUnit handles them, they do have stack traces. That might be what's happening here.

If that's the case, it still wouldn't explain why it only happens on PHP 7.2, though. Perhaps something changed in Zend that we have to update our error suppression/restoration logic for?

Krinkle triaged this task as High priority.EditedSep 23 2018, 4:39 AM

Actually, I'm more concerned with the error itself than the fact that it isn't being suppressed.

Given the ternary that was being introduced, this means we have a value being passed here that is "not an object" but also "thruthy". That seems bad, ver bad. In fact, it might mean that this code isn't working and just always returning zero.

In production I see a suspiciously high number of warnings from this code being logged. They are all in the suppressed "error-json" channel. But it's still bad, because that means we're always returning zero instead of the actual number of affected rows, which could be causing silently failures and corruption in many places.

includes/libs/rdbms
class DatabaseMysqlBase {
	/** @param ResultWrapper|resource */
	function numRows( $res ) {
		if ( $res instanceof ResultWrapper ) {
			$res = $res->result;
		}
		Wikimedia\suppressWarnings();
		$n = $res ? $this->mysqlNumRows( $res ) : 0;
		Wikimedia\restoreWarnings();
	}
}
class DatabaseMysqli {
	/** @param mysqli_result */
	function mysqlNumRows( $res ) {
		return $res->num_rows;
	}
}
Logstash error-json channel
{
 "type":"ErrorException",
 "message":"PHP Notice: Cannot access property on non-object",
 "code":0,
 "file":"/srv/mediawiki/php-1.32.0-wmf.22/includes/libs/rdbms/database/DatabaseMysqli.php",
 "line":233,

 "suppressed":true,

 "backtrace":[{
   "file":"/srv/mediawiki/php-1.32.0-wmf.22/includes/libs/rdbms/database/DatabaseMysqli.php","line":233,
   "class":"MWExceptionHandler", "type":"::", "function": "handleError",
   "args":["integer","string","string","integer","array","array"]
  },{
   "file":"/srv/mediawiki/php-1.32.0-wmf.22/includes/libs/rdbms/database/DatabaseMysqlBase.php","line":362,
   "class":"Wikimedia\\Rdbms\\DatabaseMysqli", "type":"->", "function":"mysqlNumRows",
   "args":["boolean"]
  },{
   "file":"/srv/mediawiki/php-1.32.0-wmf.22/includes/libs/rdbms/database/Database.php","line":1257,
    "function":"numRows","class":"Wikimedia\\Rdbms\\DatabaseMysqlBase",
    "type":"->","args":["boolean"]
  },{
   "file":"/srv/mediawiki/php-1.32.0-wmf.22/includes/libs/rdbms/database/Database.php","line":1155,
   "class":"Wikimedia\\Rdbms\\Database","type":"->","function":"doProfiledQuery",
   "args":["string","string","boolean","string"]
  },{
   "file":"/srv/mediawiki/php-1.32.0-wmf.22/includes/libs/rdbms/database/Database.php","line":3893,
   "class":"Wikimedia\\Rdbms\\Database","type":"->","function":"query",

This says Database->doProfiledQuery is calling DatabaseMysqlBase->numRows with a boolean, which then ends up calling DatabaseMysqli->mysqlNumRows().

Given the ternary, this must mean that the boolean value is boolean true.

The value that Database->doProfiledQuery passes to DatabaseMysqlBase->numRows comes from DatabaseMysqli->doQuery. That method is supposed to return mysqli_result or false. It is not expected to return true. Yet, the PHP docs disagree with ours:

https://secure.php.net/manual/en/mysqli.query.php

Returns false on failure. For successful SELECT.... queries mysqli_query() will return a mysqli_result object. For other successful queries mysqli_query() will return true.

On the other hand, MediaWiki only calls numRows if the query was a read query. If it was a write query, it calls affectedRows instead of numRows.

includes/lib/rdbms
# Database::doProfiledQuery

	$isWrite ? $this->affectedRows() : $this->numRows( $ret )

So, we're looking for a query that is:

  • .. common on Special:Preferences in production,
  • .. common in our unit tests,
  • .. makes mysqli_query() return true (so not an obvious read query),
  • .. makes MediaWiki $isWrite set to false (so not an obvious write query),

And on top of that, this query is happening in a context that in production (on HHVM) emits a PHP Notice that is correctly suppressed, but with PHPUnit on PHP 7.2, is not being suppressed.

Thoughts?

Krinkle edited projects, added Wikimedia-production-error; removed MW-1.32-notes (WMF-deploy-2018-08-21 (1.32.0-wmf.18)), Wikimedia-production-error (ARCHIVED -- Shared Build Failure).Sep 23 2018, 4:39 AM
Krinkle moved this task from Untriaged to Older on the Wikimedia-production-error board.
Legoktm added a comment.Sep 23 2018, 6:44 PM

I did a bit of debugging:

diff --git a/includes/libs/rdbms/database/Database.php b/includes/libs/rdbms/database/Database.php
index e276d09992..3a87c46d74 100644
--- a/includes/libs/rdbms/database/Database.php
+++ b/includes/libs/rdbms/database/Database.php
@@ -1250,6 +1250,17 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware
                        $this->rttEstimate = $queryRuntime;
                }
 
+               if ( !$isWrite ) {
+                       if ( $ret instanceof ResultWrapper ) {
+                               $realRes = $ret->result;
+                               if ( $realRes === true ) {
+                                       wfDebugLog( 'test', "non-write but \$ret->result is true!: $sql" );
+                               }
+                       } elseif ( $ret === true ) {
+                               wfDebugLog( 'test', "non-write but \$ret is true!: $sql" );
+                       }
+               }
+
                $this->trxProfiler->recordQueryCompletion(
                        $queryProf,
                        $startTime,

Based on the debug logs, my guess is that the issue is relating to temporary tables, in which case $isWrite will be false, since it's not a real write query, but in terms of affected rows / num rows, it *is* a write query.

Tgr added a comment.Sep 23 2018, 11:50 PM

T202806 does not involve any temporary tables, though.

Tgr added a comment.Sep 24 2018, 12:04 AM
In T201900#4609306, @Tgr wrote:

T202806 does not involve any temporary tables, though.

In that case, the query triggering the error seems to be COMMIT.

• Imarlier reassigned this task from aaron to Krinkle.Sep 24 2018, 8:23 PM
• Imarlier moved this task from Inbox, needs triage to Doing (old) on the Performance-Team board.
gerritbot added a comment.Sep 28 2018, 11:45 PM

Change 463577 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@master] rdbms: Document a bunch of stuff about query verbs

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

gerritbot added a project: Patch-For-Review.Sep 28 2018, 11:45 PM
gerritbot added a comment.Oct 1 2018, 3:55 PM

Change 463577 merged by jenkins-bot:
[mediawiki/core@master] rdbms: Document a bunch of stuff about query verbs

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

ReleaseTaggerBot added a project: MW-1.32-notes (WMF-deploy-2018-10-02 (1.32.0-wmf.24)).Oct 1 2018, 4:00 PM
kostajh subscribed.Oct 1 2018, 5:25 PM
Umherirrender mentioned this in T205907: Database crash when closing connection.Oct 1 2018, 6:53 PM
awight merged a task: T205907: Database crash when closing connection.Oct 1 2018, 7:11 PM
awight subscribed.
gerritbot added a comment.Oct 1 2018, 7:11 PM

Change 463822 had a related patch set uploaded (by Awight; owner: Awight):
[mediawiki/core@master] Don't run numRows on a "true" result

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

gerritbot added a comment.Oct 2 2018, 12:15 AM

Change 463871 had a related patch set uploaded (by Awight; owner: Awight):
[mediawiki/core@master] Database result type is mostly opaque to our classes

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

Krinkle moved this task from Doing (old) to Blocked (old) on the Performance-Team board.Oct 2 2018, 1:43 AM
gerritbot added a comment.Oct 8 2018, 3:50 AM

Change 465114 had a related patch set uploaded (by Tim Starling; owner: Tim Starling):
[mediawiki/core@master] Fix guarding of MySQL's numRows()

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

gerritbot added a comment.Oct 8 2018, 7:17 PM

Change 465114 merged by jenkins-bot:
[mediawiki/core@master] Fix guarding of MySQL's numRows()

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

ReleaseTaggerBot edited projects, added MW-1.32-notes (WMF-deploy-2018-10-16 (1.32.0-wmf.26)); removed MW-1.32-notes (WMF-deploy-2018-10-02 (1.32.0-wmf.24)).Oct 8 2018, 8:00 PM
gerritbot added a comment.Oct 8 2018, 11:30 PM

Change 465295 had a related patch set uploaded (by Krinkle; owner: Tim Starling):
[mediawiki/core@wmf/1.32.0-wmf.24] Fix guarding of MySQL's numRows()

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

gerritbot added a comment.Oct 8 2018, 11:54 PM

Change 465295 merged by jenkins-bot:
[mediawiki/core@wmf/1.32.0-wmf.24] Fix guarding of MySQL's numRows()

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

ReleaseTaggerBot edited projects, added MW-1.32-notes (WMF-deploy-2018-10-02 (1.32.0-wmf.24)); removed MW-1.32-notes (WMF-deploy-2018-10-16 (1.32.0-wmf.26)).Oct 9 2018, 12:01 AM
Stashbot subscribed.Oct 9 2018, 12:04 AM

Mentioned in SAL (#wikimedia-operations) [2018-10-09T00:04:00Z] <krinkle@deploy1001> Synchronized php-1.32.0-wmf.24/includes/libs/rdbms/database: T201900 - I8ae754a2518 (duration: 00m 59s)

Krinkle closed this task as Resolved.Oct 10 2018, 8:53 PM
Krinkle reassigned this task from Krinkle to tstarling.
Krinkle removed a project: Patch-For-Review.
gerritbot added a comment.Mar 1 2019, 1:20 AM

Change 463871 abandoned by Aaron Schulz:
Database result type is mostly opaque to our classes

Reason:
Superseded by another patch

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

gerritbot added a comment.Mar 1 2019, 1:20 AM

Change 463822 abandoned by Aaron Schulz:
Guard numRows, not appropriate for some queries

Reason:
Superseded by another patch

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

gerritbot added a comment.Mar 1 2019, 1:30 AM

Change 463871 restored by Aaron Schulz:
Database result type is mostly opaque to our classes

Reason:
Gah, I meant the one in another browser tab

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

gerritbot added a comment.Jul 19 2019, 1:31 PM

Change 463871 abandoned by Awight:
Database result type is mostly opaque to our classes

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

• mmodell changed the subtype of this task from "Task" to "Production Error".Aug 28 2019, 11:09 PM
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL · Credits