Various PHP warnings are breaking FormattedRCFeed
Closed, ResolvedPublic

Description

These seem to all occur together

\nNotice: Undefined index: HASH in /srv/mediawiki/tags/2017-02-02_07:24:01/includes/cache/MessageCache.php on line 594
\nNotice: Undefined index: HASH in /srv/mediawiki/tags/2017-02-02_07:24:01/includes/cache/MessageCache.php on line 727

\nWarning: __construct() expects exactly 1 parameter, 0 given in /srv/mediawiki/tags/2017-02-02_07:24:01/includes/rcfeed/FormattedRCFeed.php on line 37
\nCatchable fatal error: Argument 1 passed to FormattedRCFeed::__construct() must be an instance of array, undefined variable given in /srv/mediawiki/tags/2017-02-02_07:24:01/includes/rcfeed/FormattedRCFeed.php on line 37

\nWarning: Destructor threw an object exception: exception 'DBTransactionError' with message 'LBFactory::shutdown: transaction round 'MWCallableUpdate::doUpdate' still running.' in /srv/mediawiki/tags/2017-02-02_07:24:01/includes/libs/rdbms/lbfactory/LBFactory.php:210\nStack trace:\n#0 /srv/mediawiki/tags/2017-02-02_07:24:01/includes/libs/rdbms/lbfactory/LBFactory.php(138): LBFactory->commitMasterChanges()\n#1 /srv/mediawiki/tags/2017-02-02_07:24:01/includes/libs/rdbms/lbfactory/LBFactory.php(124): LBFactory->shutdown()\n#2 /srv/mediawiki/tags/2017-02-02_07:24:01/includes/libs/rdbms/lbfactory/LBFactory.php(571): LBFactory->destroy()\n#3 (): LBFactory->__destruct()\n#4 {main}

Might be related to https://gerrit.wikimedia.org/r/#/c/330833/

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptFeb 2 2017, 7:42 AM
Nikerabbit renamed this task from Multiple PHP warnings in master to Multiple PHP warnings in master [FormattedRCFeed].Feb 2 2017, 7:47 AM

I could not correlate this with web requests, so likely coming via JobQueue.

Nemo_bis added a subscriber: Nemo_bis.EditedFeb 2 2017, 10:15 AM

We also got a few hundreds of these:

13.09 -rakkaus:#mediawiki-i18n- (29 lines skipped) \nNotice: JobQueueGroup::__destruct: 2 buffered job(s) of type(s) RecentChangesUpdateJob, EnotifNotifyJob never inserted. in 
          /srv/mediawiki/tags/2017-01-23_17:34:04/includes/jobqueue/JobQueueGroup.php on line 449

11.00 -rakkaus:#mediawiki-i18n- (15 lines skipped) [Thu Feb  2 11:00:46 2017] [hphp] [11982:7f84cc7ff700:5089:000006] [] \nNotice: JobQueueGroup::__destruct: 1 buffered job(s) 
          of type(s) RecentChangesUpdateJob never inserted. in /srv/mediawiki/tags/2017-02-02_07:24:01/includes/jobqueue/JobQueueGroup.php on line 449

which

11.16 <+Nikerabbit> Nemo_bis: according to timestamps, it is related to the same issue, but not there always, hence not in my paste

I'll also note that this is quite spammy for #mediawiki-i18n, and given the schema change for expiring user groups, I am not sure it is safe to rollback to previously deployed version.

Nikerabbit triaged this task as High priority.Feb 2 2017, 10:32 AM

This also broke our IRC relay ($wgRCFeeds['irc'] = array( 'formatter' => 'IRCColourfulRCFeedFormatter', ...) ).

What I ended up doing is reverting 39a6e3dc4d84ed55bdcfefad2fa04dd2bcb867bd locally.

After that only these notices show up (suggesting they are caused by something else)

[Thu Feb  2 11:31:08 2017] [hphp] [11982:7f84fe3ff700:6216:000001] [] \nNotice: Undefined index: HASH in /srv/mediawiki/tags/2017-02-02_10:27:40/includes/cache/MessageCache.php on line 594
[Thu Feb  2 11:31:08 2017] [hphp] [11982:7f84fe3ff700:6216:000002] [] \nNotice: Undefined index: HASH in /srv/mediawiki/tags/2017-02-02_10:27:40/includes/cache/MessageCache.php on line 727
Anomie added a subscriber: Anomie.Feb 2 2017, 2:37 PM

After that only these notices show up (suggesting they are caused by something else)

[Thu Feb  2 11:31:08 2017] [hphp] [11982:7f84fe3ff700:6216:000001] [] \nNotice: Undefined index: HASH in /srv/mediawiki/tags/2017-02-02_10:27:40/includes/cache/MessageCache.php on line 594
[Thu Feb  2 11:31:08 2017] [hphp] [11982:7f84fe3ff700:6216:000002] [] \nNotice: Undefined index: HASH in /srv/mediawiki/tags/2017-02-02_10:27:40/includes/cache/MessageCache.php on line 727

I filed T157033: Notice: Undefined index: HASH in /srv/mediawiki/php-1.29.0-wmf.10/includes/cache/MessageCache.php on line 594 for that one.

If the RCFeed config refactor causes JobQueue issues, reverting before branch cut sounds good to me. @Krinkle?

Krinkle claimed this task.Feb 2 2017, 8:02 PM
Krinkle added a project: Regression.

Change 335693 had a related patch set uploaded (by Krinkle):
rcfeed: FormattedRCFeed constructor should match parent class

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

Krinkle added a comment.EditedFeb 2 2017, 8:06 PM

@Ottomata commit rMW39a6e3dc4d84ed55bdcfefad2fa04dd2bcb867bd did not make the branch cut this week so it's not affecting production yet. However it does need fixing before Tuesday. I've submitted https://gerrit.wikimedia.org/r/#/c/335693/ which should address the FormattedRCFeed warning.

Mentioned in SAL (#wikimedia-operations) [2017-02-02T20:14:21Z] <twentyafterfour> rolling back to wmf.9 due to T156996

Change 335693 merged by jenkins-bot:
rcfeed: FormattedRCFeed constructor should match parent class

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

Krinkle closed this task as Resolved.Feb 2 2017, 9:54 PM

Mentioned in SAL (#wikimedia-operations) [2017-02-02T23:33:58Z] <twentyafterfour@tin> Synchronized php-1.29.0-wmf.10/includes/cache/MessageCache.php: deploy I5b84b1ae4a9c7b710ee452c61d7d9d6076ec9e6a refs T156996 (duration: 00m 45s)

This also broke our IRC relay ($wgRCFeeds['irc'] = array( 'formatter' => 'IRCColourfulRCFeedFormatter', ...) ).

Filed as T157106: IRC relay broken in master

Nikerabbit reopened this task as Open.Feb 3 2017, 7:33 AM

I have to reopen:

[Fri Feb  3 08:32:28 2017] [hphp] [28680:7fe5b13ff700:18:000001] [] \nNotice: Undefined index: formatter in /srv/mediawiki/tags/2017-02-03_07:22:50/includes/rcfeed/FormattedRCFeed.php on line 56
[Fri Feb  3 08:32:28 2017] [hphp] [28680:7fe5b13ff700:18:000002] [] \nNotice: Undefined index: formatter in /srv/mediawiki/tags/2017-02-03_07:22:50/includes/rcfeed/FormattedRCFeed.php on line 56
[Fri Feb  3 08:32:28 2017] [hphp] [28680:7fe5b13ff700:18:000003] [] \nFatal error: Cls: Expected string or object in /srv/mediawiki/tags/2017-02-03_07:22:50/includes/rcfeed/FormattedRCFeed.php on line 56
[Fri Feb  3 08:32:28 2017] [hphp] [28680:7fe5b13ff700:18:000004] [] \nNotice: JobQueueGroup::__destruct: 1 buffered job(s) of type(s) RecentChangesUpdateJob never inserted. in /srv/mediawiki/tags/2017-02-03_07:22:50/includes/jobqueue/JobQueueGroup.php on line 449
[Fri Feb  3 08:32:28 2017] [hphp] [28680:7fe5b13ff700:18:000005] [] \nNotice: Uncommitted DB writes (transaction from Database::query (User::idFromName)). in /srv/mediawiki/tags/2017-02-03_07:22:50/includes/libs/rdbms/database/Database.php on line 3445
[Fri Feb  3 08:32:28 2017] [hphp] [28680:7fe5b13ff700:18:000006] [] \nNotice: DB transaction writes or callbacks still pending (RecentChange::save). in /srv/mediawiki/tags/2017-02-03_07:22:50/includes/libs/rdbms/database/Database.php on line 3451
[Fri Feb  3 08:32:28 2017] [hphp] [28680:7fe5b13ff700:18:000007] [] \nWarning: Destructor threw an object exception: exception 'DBTransactionError' with message 'LBFactory::shutdown: transaction round 'MWCallableUpdate::doUpdate' still running.' in /srv/mediawiki/tags/2017-02-03_07:22:50/includes/libs/rdbms/lbfactory/LBFactory.php:210\nStack trace:\n#0 /srv/mediawiki/tags/2017-02-03_07:22:50/includes/libs/rdbms/lbfactory/LBFactory.php(138): LBFactory->commitMasterChanges()\n#1 /srv/mediawiki/tags/2017-02-03_07:22:50/includes/libs/rdbms/lbfactory/LBFactory.php(124): LBFactory->shutdown()\n#2 /srv/mediawiki/tags/2017-02-03_07:22:50/includes/libs/rdbms/lbfactory/LBFactory.php(571): LBFactory->destroy()\n#3 (): LBFactory->__destruct()\n#4 {main}
Krinkle renamed this task from Multiple PHP warnings in master [FormattedRCFeed] to PHP Warning: construct() expects exactly 1 parameter in FormattedRCFeed.php.Feb 4 2017, 3:18 AM
Krinkle closed this task as Resolved.
Krinkle renamed this task from PHP Warning: construct() expects exactly 1 parameter in FormattedRCFeed.php to Various PHP warnings are breaking FormattedRCFeed.
Krinkle updated the task description. (Show Details)
Krinkle reopened this task as Open.Feb 4 2017, 3:21 AM

Change 335969 had a related patch set uploaded (by Krinkle):
rcfeed: Ensure formatter (and other params) is passed to RCFeedEngine

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

It has been running for some minutes now. I have not spotted any issues.

On beta we have includes/rcfeed/FormattedRCFeed.php that raises: PHP Fatal Error: Cls: Expected string or object

{
  "file": "/srv/mediawiki/php-master/includes/rcfeed/FormattedRCFeed.php",
  "line": 56
},
{
  "file": "/srv/mediawiki/php-master/includes/changes/RecentChange.php",
  "line": 421,
  "function": "notify",
  "class": "FormattedRCFeed",
  "type": "->",
  "args": [
    "RecentChange",
    "string"
  ]
},
{
  "file": "/srv/mediawiki/php-master/includes/logging/LogEntry.php",
  "line": 727,
  "function": "notifyRCFeeds",
  "class": "RecentChange",
  "type": "->",
  "args": []
},
{
  "file": "/srv/mediawiki/php-master/includes/deferred/MWCallableUpdate.php",
  "line": 28,
  "function": "Closure$ManualLogEntry::publish",
  "args": []
},
{
  "file": "/srv/mediawiki/php-master/includes/deferred/DeferredUpdates.php",
  "line": 263,
  "function": "doUpdate",
  "class": "MWCallableUpdate",
  "type": "->",
  "args": []
},
{
  "file": "/srv/mediawiki/php-master/includes/deferred/DeferredUpdates.php",
  "line": 225,
  "function": "runUpdate",
  "class": "DeferredUpdates",
  "type": "::",
  "args": [
    "MWCallableUpdate",
    "LBFactoryMulti",
    "integer"
  ]
},
{
  "file": "/srv/mediawiki/php-master/includes/deferred/DeferredUpdates.php",
  "line": 133,
  "function": "execute",
  "class": "DeferredUpdates",
  "type": "::",
  "args": [
    "array",
    "string",
    "integer"
  ]
},
{
  "file": "/srv/mediawiki/php-master/includes/MediaWiki.php",
  "line": 899,
  "function": "doUpdates",
  "class": "DeferredUpdates",
  "type": "::",
  "args": [
    "string"
  ]
},
{
  "file": "/srv/mediawiki/php-master/includes/MediaWiki.php",
  "line": 728,
  "function": "restInPeace",
  "class": "MediaWiki",
  "type": "->",
  "args": [
    "string"
  ]
},
{
  "function": "Closure$MediaWiki::doPostOutputShutdown",
  "args": []
}

Change 335969 merged by jenkins-bot:
rcfeed: Ensure formatter (and other params) is passed to RCFeedEngine

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

Krinkle closed this task as Resolved.Feb 6 2017, 11:34 PM

Forgot to ping this task yesterday, but when https://gerrit.wikimedia.org/r/335969 the beta cluster log spam stopped :-} Thank you Timo!