Page MenuHomePhabricator

Log spam in resource loader log "Unexpected general module"
Closed, ResolvedPublic

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

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.

Event Timeline

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJul 27 2016, 8:38 AM
hashar added a project: Performance-Team.
hashar added a subscriber: hashar.

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

Krinkle added a subscriber: Krinkle.
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.

Thank you Timo for the detailed explanation :)