Various PHP warnings are breaking FormattedRCFeed
Closed, ResolvedPublic
Actions

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/

Related Objects
Search...

Status	Assigned	Task
		· · ·
Open	None	T41480 Bugs affecting translatewiki.net (errors from MediaWiki master) (tracking)
Resolved	thcipriani	T155526 MW-1.29.0-wmf.11 deployment blockers
Resolved	Krinkle	T156996 Various PHP warnings are breaking FormattedRCFeed
		· · ·

Nikerabbit created this task.Feb 2 2017, 7:42 AM

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptFeb 2 2017, 7:42 AM

Nikerabbit added a parent task: T41480: Bugs affecting translatewiki.net (errors from MediaWiki master) (tracking).Feb 2 2017, 7:44 AM

Nikerabbit mentioned this in T156901: Database updater fails.

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.

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

Nemo_bis added a subscriber: Ottomata.Feb 2 2017, 10:17 AM

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.

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

In T156996#2992713, @Nikerabbit wrote:

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

gerritbot added a project: Patch-For-Review.Feb 2 2017, 8:04 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.

Reedy added a project: MW-1.29-release (WMF-deploy-2017-01-31_(1.29.0-wmf.10)).Feb 2 2017, 8:13 PM

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

mmodell added a parent task: T155525: MW-1.29.0-wmf.10 deployment blockers.Feb 2 2017, 9:53 PM

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

Krinkle removed a parent task: T155525: MW-1.29.0-wmf.10 deployment blockers.

ReleaseTaggerBot added projects: MW-1.29-release (WMF-deploy-2017-02-07_(1.29.0-wmf.11)), MW-1.29-release-notes.Feb 2 2017, 10:00 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)

Nikerabbit mentioned this in T157106: IRC relay broken in master.Feb 3 2017, 6:52 AM

In T156996#2992713, @Nikerabbit wrote:

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

Filed as T157106: IRC relay broken in master

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}

Nikerabbit removed a project: Patch-For-Review.Feb 3 2017, 7:33 AM

hashar added a parent task: T155526: MW-1.29.0-wmf.11 deployment blockers.Feb 3 2017, 2:18 PM

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 removed projects: MW-1.29-release-notes, MW-1.29-release (WMF-deploy-2017-02-07_(1.29.0-wmf.11)), MW-1.29-release (WMF-deploy-2017-01-31_(1.29.0-wmf.10)).

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

gerritbot added a project: Patch-For-Review.Feb 4 2017, 3:35 AM

@Nikerabbit Can you verify that patch https://gerrit.wikimedia.org/r/335969 resolves it?

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": []
}