Page MenuHomePhabricator

Logs flooded with "MessageCache::parse called by ..."
Closed, ResolvedPublic

Description

fluorine's globatitlefail.log grows by about 1.2-1.5MB/s & 10k lines per second with messages like this:

2014-12-15 07:14:47 mw1244 enwiki: MessageCache::parse called by Message::toString/Message::parseText/MessageCache::parse with no title set.
2014-12-15 07:14:47 mw1040 thwiki: MessageCache::parse called by Message::toString/Message::parseText/MessageCache::parse with no title set.
2014-12-15 07:14:47 mw1095 ruwiki: MessageCache::parse called by Message::toString/Message::parseText/MessageCache::parse with no title set.
2014-12-15 07:14:47 mw1109 ruwiki: MessageCache::parse called by Message::toString/Message::parseText/MessageCache::parse with no title set.
2014-12-15 07:14:47 mw1144 wikidatawiki: RequestContext::getTitle called by AbuseFilterHooks::filterEdit/AbuseFilter::filterAction/RequestContext::getTitle with no title set.
2014-12-15 07:14:47 mw1096 enwiki: MessageCache::parse called by Message::toString/Message::parseText/MessageCache::parse with no title set.
2014-12-15 07:14:47 mw1102 zhwiki: MessageCache::parse called by Message::toString/Message::parseText/MessageCache::parse with no title set.
2014-12-15 07:14:47 mw1180 enwiki: MessageCache::parse called by Message::toString/Message::parseText/MessageCache::parse with no title set.
2014-12-15 07:14:47 mw1076 enwiki: MessageCache::parse called by Message::toString/Message::parseText/MessageCache::parse with no title set.
2014-12-15 07:14:47 mw1024 enwiki: MessageCache::parse called by Message::toString/Message::parseText/MessageCache::parse with no title set.

This has been going on for a while and has resulted into this:

-rw-r--r-- 1 udp2log udp2log  90M Nov 17 06:25 archive/globaltitlefail.log-20141117.gz
-rw-r--r-- 1 udp2log udp2log  80M Nov 18 06:25 archive/globaltitlefail.log-20141118.gz
-rw-r--r-- 1 udp2log udp2log 234M Nov 19 06:25 archive/globaltitlefail.log-20141119.gz
-rw-r--r-- 1 udp2log udp2log 1.6G Nov 20 06:25 archive/globaltitlefail.log-20141120.gz
-rw-r--r-- 1 udp2log udp2log 3.0G Nov 21 06:25 archive/globaltitlefail.log-20141121.gz
-rw-r--r-- 1 udp2log udp2log 2.9G Nov 22 06:25 archive/globaltitlefail.log-20141122.gz
-rw-r--r-- 1 udp2log udp2log 3.0G Nov 23 06:25 archive/globaltitlefail.log-20141123.gz

...which is currently throwing fluorine off-balance with regards to disk usage.

https://gerrit.wikimedia.org/r/#/c/162149/1 seems to be the culprit and needs to be reverted (I'll do it soon unless I hear otherwise). The logspam has been diagnosed before and an attempt to fix it went with https://gerrit.wikimedia.org/r/#/c/163204/2 but apparently it wasn't enough.

Event Timeline

faidon raised the priority of this task from to Unbreak Now!.
faidon updated the task description. (Show Details)
faidon added a project: MediaWiki-Core-Team.
faidon changed Security from none to None.
faidon subscribed.

Those lines don't seem too useful to identify the code which needs fixing, so disabling the log is probably no big deal. Alternatively, sample it 1:10000 or even more (cf. 1afd16f12e3082fef68faf6a2ea4c29886d47310)?

https://gerrit.wikimedia.org/r/#/c/179519/ is going to make the log messages more useful, but it hasn't been deployed yet. Sampling the log sounds like a good idea though.

Change 179870 had a related patch set uploaded (by Legoktm):
Sample the GlobalTitleFail log at 1:10000

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

Patch-For-Review

https://gerrit.wikimedia.org/r/#/c/179519/ is going to make the log messages more useful, but it hasn't been deployed yet. Sampling the log sounds like a good idea though.

This seems not enough, because MessageCache::parse contains its own log:
wfDebugLog( 'GlobalTitleFail', METHOD . ' called by ' . wfGetAllCallers() . ' with no title set.' );

Change 179870 merged by jenkins-bot:
Sample the GlobalTitleFail log at 1:10000

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

(Adding @hashar and @mmodell in case this throws off beta cluster at all)