Page MenuHomePhabricator

Log spam: "Multiple writes to a write-once: limitreportdata discussiontools-limitreport-timeusage"
Closed, ResolvedPublic

Description

I've noticed these warnings when browsing DiscussionTools-related error logs: "Multiple writes to a write-once: limitreportdata discussiontools-limitreport-timeusage". They greatly increased in rate on 2022-11-10: https://logstash.wikimedia.org/goto/8c490d9343a900fa4df1f68f160fd300

image.png (465×2 px, 64 KB)

The warning is logged here from Parsoid code: https://codesearch.wmcloud.org/search/?q=Multiple+writes+to+a+write-once

The value is written here from DiscussionTools code: https://codesearch.wmcloud.org/search/?q=discussiontools-limitreport-timeusage&files=%5C.php%24 (just once, as far as I can tell…)

Can anyone explain what this really means, and how do we fix it?

Event Timeline

(it's almost all on mediawikiwiki)

(but this might be just because DiscussionTools is enabled there on almost all pages, due to wgExtraSignatureNamespaces including NS_MAIN, and not that interesting)

Why is DiscussionTools using StubMetadataCollector instead of a real ParserOutput? That seems to be the first question -- StubMetadataCollector should only be used in the 'standalone' mode of Parsoid, not the integrated mode.

But once you're using a "real" ParserOutput the warnings will disappear but the issue won't -- it seems to be that the limit report data is being overwritten at some point. Is that intentional? We're "losing" the old limit report data when we do this -- AFAIK the limit report really is meant to be written exactly once, in OutputPage.

Krinkle triaged this task as Medium priority.Nov 17 2022, 4:50 PM
Krinkle moved this task from Untriaged to Nov 2022 on the Wikimedia-production-error board.

I don't think DiscussionTools using StubMetadataCollector, we even typehint ParserOutput. I think something else somewhere is doing weird stuff to the ParserOutput we generate.

Is there anyway we can get a stack trace? It's coming from /rpc/RunSingleJob.php so likely Parsoid isn't being configured correctly in "headless" mode.

I suspect what's happening is that DiscussionTools is setting a limit report on a "real" ParserOutput (there are type hints in CommentFormatter::addDiscussionTools, so it has to be real at that point), but then someone is doing:

$stub = new StubMetadataCollector();
$stub->setLimitReportData(...something...);
// ...some time later...
$parserOutputFromDiscussionTools->collectMetadata($stub);

which then triggers the warning because the limit report data from the stub and from the 'real' ParserOutput can't be merged, and instead one of them is being dropped on the floor.

The collectMetadata method is only invoked twice, according to codesearch and in both cases the $stub of the example above would be the "thing passed in" to DataAccess::parseWikitext(... $stub ...) or DataAccess::preprocessWikitext(... $stub ...) and so would have to have the limit report already present in $stub before one of those methods was invoked. So who is creating a StubMetadataCollector and stuffing it with limit report data?

That's where the trail goes a bit cold and a stack trace would help. Most of the calls which construct a StubMetadataCollector are in testing or standalone/API-mode code and *shouldn't* be part of the stack trace here. (Of course, I can always be surprised.)

The likeliest culprits, tain entry points from src/Parsoid.php, which create a StubMetadataCollector are as follows:

  • From Parsoid::wikitext2html(), only if the final $metadata parameter is null (it shouldn't be!), but it's calling parseWikitext on an empty stub metadata collector so it's hard to see how a preexisting limit report could be there, and AFAICT it doesn't leak/expose its stub metadatacollector outside the method.
  • From Parsoid::wikitext2lint() -- always creates a new empty StubMetadataCollector but (a) it's empty, so it won't have a limit report in it, and (b) it's thrown away and doesn't escape the method.
  • From Parsoid::dom2wikitext() - same as previous. Always creates a SMC but its empty and doesn't escape.
  • From Parsoid::pb2pb() - again, always creates an empty SMC which doesn't escape
  • From Parsoid::substTopLevelTemplates() - same: empty SMC which doesn't escape

So I've proved either that (a) this bug is impossible :) or (b) some of my logic here is wrong, or (c) codesearch isn't finding all the relevant cases (calls to collectMetadata or creation sites for StubMetadataCollector).

This seems to have gone away on 2023-03-17: https://logstash.wikimedia.org/goto/8733164afe4a990eade2ebcaca34aaf4

image.png (540×2 px, 65 KB)

I don't know the cause, but I don't really care to find out.