Page MenuHomePhabricator
Create Task
Maniphest T141426

Log spam in resource loader log "Unexpected general module"
Closed, ResolvedPublicPRODUCTION ERROR
Actions

Description

Starting on the 21st the logsize of resourceloader.log grew massively with the uncompressed current log being bigger than 320 GBs and triggering Icinga diskspace alerts for the fluorine log host:

-rw-r--r-- 1 udp2log udp2log  29M Jul 18 06:25 resourceloader.log-20160718.gz
-rw-r--r-- 1 udp2log udp2log  29M Jul 19 06:24 resourceloader.log-20160719.gz
-rw-r--r-- 1 udp2log udp2log  32M Jul 20 06:25 resourceloader.log-20160720.gz
-rw-r--r-- 1 udp2log udp2log 887M Jul 21 06:25 resourceloader.log-20160721.gz
-rw-r--r-- 1 udp2log udp2log 8.1G Jul 22 06:25 resourceloader.log-20160722.gz
-rw-r--r-- 1 udp2log udp2log  14G Jul 23 06:25 resourceloader.log-20160723.gz
-rw-r--r-- 1 udp2log udp2log  13G Jul 24 06:25 resourceloader.log-20160724.gz
-rw-r--r-- 1 udp2log udp2log  13G Jul 25 06:25 resourceloader.log-20160725.gz
-rw-r--r-- 1 udp2log udp2log  15G Jul 26 06:25 resourceloader.log-20160726.gz

The log is full of log lines like P3581

P3581 Sample logs for resource loader log
12016-07-26 08:58:27 [V5cmMwpAIC0AAFcrsEsAAAAI] mw1175 enwiki 1.28.0-wmf.11 resourceloader DEBUG: Unexpected general module "user" in styles queue. {"module":"user"}
22016-07-26 08:58:27 [V5cmMwpAAEAAAUtIw4AAAABK] mw1269 svwiki 1.28.0-wmf.11 resourceloader DEBUG: Unexpected general module "ext.gadget.Teckenstorlek" in styles queue. {"module":"ext.gadget.Teckenstorlek"}
32016-07-26 08:58:27 [V5cmMwpAMF0AAJ5ZcWcAAAAF] mw1258 zhwiki 1.28.0-wmf.11 resourceloader DEBUG: Unexpected general module "ext.gadget.hideConversionTab" in styles queue. {"module":"ext.gadget.hideConversionTab"}
42016-07-26 08:58:27 [V5cmMwpAIDcAACeRfb0AAAAS] mw1185 enwiki 1.28.0-wmf.11 resourceloader DEBUG: Unexpected general module "oojs-ui-core.styles" in styles queue. {"module":"oojs-ui-core.styles"}
52016-07-26 08:58:27 [V5cmMwpAIDYAACLiuY8AAABD] mw1184 svwiki 1.28.0-wmf.11 resourceloader DEBUG: Unexpected general module "ext.globalCssJs.site.styles" in styles queue. {"module":"ext.globalCssJs.site.styles"}
62016-07-26 08:58:27 [V5cmMwpAAD0AAaOsAB0AAAAW] mw1266 rowiki 1.28.0-wmf.11 resourceloader DEBUG: Unexpected general module "user" in styles queue. {"module":"user"}
72016-07-26 08:58:27 [V5cmMwpAAEAAAUtIw4AAAABK] mw1269 svwiki 1.28.0-wmf.11 resourceloader DEBUG: Unexpected general module "ext.gadget.UppladdningarContentSub" in styles queue. {"module":"ext.gadget.UppladdningarContentSub"}
82016-07-26 08:58:27 [V5cmMwpAICkAAB7-OAsAAABX] mw1171 enwiki 1.28.0-wmf.11 resourceloader DEBUG: Unexpected general module "ext.gadget.teahouse" in styles queue. {"module":"ext.gadget.teahouse"}
92016-07-26 08:58:27 [V5cmMgpAIDYAACLiuYcAAABT] mw1184 zhwiki 1.28.0-wmf.11 resourceloader DEBUG: Unexpected general module "ext.gadget.NavFrame" in styles queue. {"module":"ext.gadget.NavFrame"}
102016-07-26 08:58:27 [V5cmMwpAMCUAADwRtNUAAABV] mw1209 eowiki 1.28.0-wmf.11 resourceloader DEBUG: Unexpected general module "ext.gadget.EksteraLigilo" in styles queue. {"module":"ext.gadget.EksteraLigilo"}
112016-07-26 08:58:27 [V5cmMwpAEKoAAGW32c4AAABC] mw1215 enwiki 1.28.0-wmf.11 resourceloader DEBUG: Unexpected general module "mobile.usermodule.styles" in styles queue. {"module":"mobile.usermodule.styles"}
122016-07-26 08:58:27 [V5cmMwpAMF0AAJ5ZcWcAAAAF] mw1258 zhwiki 1.28.0-wmf.11 resourceloader DEBUG: Unexpected general module "ext.gadget.internalLinkHelper-altcolor" in styles queue. {"module":"ext.gadget.internalLinkHelper-altcolor"}
132016-07-26 08:58:27 [V5cmMwpAIDcAACeRfb0AAAAS] mw1185 enwiki 1.28.0-wmf.11 resourceloader DEBUG: Unexpected general module "oojs-ui.styles.icons" in styles queue. {"module":"oojs-ui.styles.icons"}
142016-07-26 08:58:27 [V5cmMwpAAEAAAUtIw4AAAABK] mw1269 svwiki 1.28.0-wmf.11 resourceloader DEBUG: Unexpected general module "ext.gadget.ValValidering" in styles queue. {"module":"ext.gadget.ValValidering"}
152016-07-26 08:58:27 [V5cmMgpAIDYAACLiuYcAAABT] mw1184 zhwiki 1.28.0-wmf.11 resourceloader DEBUG: Unexpected general module "ext.gadget.ReferenceTooltips" in styles queue. {"module":"ext.gadget.ReferenceTooltips"}

https://gerrit.wikimedia.org/r/#/c/301336/ lowered the log level for the resourceloader to "info" as an interim measure.

Related Objects

Event Timeline

MoritzMuehlenhoff created this task.Jul 27 2016, 8:38 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJul 27 2016, 8:38 AM
jcrespo added projects: Wikimedia-production-error, observability.Jul 27 2016, 8:41 AM
jcrespo added a project: MediaWiki-ResourceLoader.
jcrespo edited projects, added MediaWiki-Debug-Logger; removed observability.Jul 27 2016, 8:52 AM
hashar mentioned this in T129982: Requests to localhost spam the 'localhost' and 'xff' log buckets.Jul 27 2016, 8:53 AM
hashar updated the task description. (Show Details)
hashar moved this task from Untriaged to Dec2019/1.35.wmf.10+ on the Wikimedia-production-error board.Jul 27 2016, 8:58 AM
hashar added a project: Performance-Team.
hashar subscribed.

+ Performance-Team apparently listed as maintainers for the resource loader on the Phabricator project page https://phabricator.wikimedia.org/project/profile/274/

Krinkle removed a project: MediaWiki-Debug-Logger.Jul 27 2016, 5:38 PM
Krinkle subscribed.
Krinkle closed this task as Resolved.EditedJul 27 2016, 7:04 PM
Krinkle claimed this task.

https://gerrit.wikimedia.org/r/#/c/301336/ lowered the log level for the resourceloader to "info" as an interim measure.

Thanks!

As confusing as it might be, "Unexpected general module" is actually very much expected right now. The code from which the is message is logged is not new (been around for years). I recently identified it as an anti-pattern and introduced a debug message to track the exact scenarios in which it happens (each message includes a module name).

See T92459 / rMWa464d1d41d69: resourceloader: Track state of page-style modules.

I wrote that commit knowing that at least two modules ("site" and "user") would trigger this condition on virtually every page view. That's why I used channel "debug" at first, instead of "warning".

However, that was under the assumption production logging for "resourceloader" is only for "info" or "warning" and above, not including "debug".

Patch rOMWCb14fe92f310e: Lower loglevel for resourceloader to info should've happened long ago, and that's that.

hashar added a comment.Jul 29 2016, 2:00 PM

Thank you Timo for the detailed explanation :)

• mmodell changed the subtype of this task from "Task" to "Production Error".Aug 28 2019, 11:11 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