Page MenuHomePhabricator

PHP Unknown error: EventLoggingLegacyConverter: Failed proxying legacy EventLogging event query string to WMF Event Platform JSON: UnexpectedValueException: TemplateDataEditor is not in the list of allowed legacy schemas.
Closed, ResolvedPublicPRODUCTION ERROR

Description

Error
labels.normalized_message
[{reqId}] {exception_url}   PHP Unknown error: EventLoggingLegacyConverter: Failed proxying legacy EventLogging event query string to WMF Event Platform JSON: UnexpectedValueException: TemplateDataEditor is not in the list of allowed legacy schemas.
FrameLocationCall
from/srv/mediawiki/docroot/mediawiki.org/beacon/event/index.php(56)
#0[internal function]MWExceptionHandler::handleError(int, string, string, int, array)
#1/srv/mediawiki/docroot/mediawiki.org/beacon/event/index.php(56)trigger_error(string, int)
#2{main}
Notes

This is seen since 1.44.0-wmf.11, seems higher volume in .12 (T382363). ~230 events last two weeks, most recent.

Closest issue while searching for this: T353817: Create legacy EventLogging proxy HTTP intake (for MediaWikiPingback) endpoint to EventGate. Spitballing some tags.

See logstash for URLs.

https://logstash.wikimedia.org/goto/1e244c0cbbab2262067fa5329414a87e - log of older unknown error
https://logstash.wikimedia.org/goto/7afc8b482e020a5b7cad82a87612743c - log of the newer warning

Event Timeline

brennen changed Request URL from https://www.mediawiki.org/beacon/event?%7B%22event%22%3A%7B%22action%22%3A%22save-page-edit%22%2C%22page_id%22%3A2109178%2C%22page_title%22%3A%22Version+history%2Fdoc%22%2C%22page_namespace%22%3A10%2C%22rev_id%22%3A6969664%2C%22user_edit_count%22%3A217250%2C%22user_id%22%3A887141%2C%22user_edit_count_bucket%22%3A%221000%2B+edits%22%7D%2C%22schema%22%3A%22TemplateDataEditor%22%2C%22webHost%22%3A%22www.mediawiki.org%22%2C%22wiki%22%3A%22mediawikiwiki%22%2C%22revision%22%3A-1%7D%3B=* to https://www.mediawiki.org/beacon/event?[redacted].Jan 16 2025, 9:05 PM
brennen updated the task description. (Show Details)
brennen moved this task from Backlog to Logs/Train on the User-brennen board.

Hm, this is um, normal? T275012: TemplateDataEditor Event Platform Migration happened in 2021 so these events have been lost since then. We are now just logging these since T353817.

Looking at logstash these look like they are from mediawiki.org? I would have guessed they were some old version of MW out there or something.

Will have to investigate...

This legacy eventlogging stream was migrated in 2021. I looked up some webrequests info from this request:

select uri_host, uri_query, ip, referer, user_agent, access_method from webrequest where webrequest_source='text' and year=2025 and month=1 and day=16 and hour=14 and uri_path = '/beacon/event' and uri_query LIKE  '%TemplateDataEditor%' limit 10;

They all seem to be coming from the same IP.

@brennen I think the message is normal and legit. Perhaps we should turn down the log severity to warn instead of error?

Change #1115111 had a related patch set uploaded (by Krinkle; author: Ottomata):

[operations/mediawiki-config@master] mediawiki.org/beacon/event - don't raise error on failure

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

Change #1115111 merged by jenkins-bot:

[operations/mediawiki-config@master] mediawiki.org/beacon/event - don't raise error on failure

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

Mentioned in SAL (#wikimedia-operations) [2025-02-18T15:15:26Z] <otto@deploy2002> Started scap sync-world: Backport for [[gerrit:1115111|mediawiki.org/beacon/event - don't raise error on failure (T383939 T353817)]]

Mentioned in SAL (#wikimedia-operations) [2025-02-18T15:20:06Z] <otto@deploy2002> otto: Backport for [[gerrit:1115111|mediawiki.org/beacon/event - don't raise error on failure (T383939 T353817)]] synced to the testservers (https://wikitech.wikimedia.org/wiki/Mwdebug)

Mentioned in SAL (#wikimedia-operations) [2025-02-18T15:27:38Z] <otto@deploy2002> Finished scap sync-world: Backport for [[gerrit:1115111|mediawiki.org/beacon/event - don't raise error on failure (T383939 T353817)]] (duration: 12m 12s)

Error
normalized_message
[{reqId}] {exception_url}   PHP Warning: EventLoggingLegacyConverter: Failed proxying legacy EventLogging event query string to WMF Event Platform JSON: UnexpectedValueException: TemplateDataEditor is not in the list of allowed legacy schemas.
FrameLocationCall
from/srv/mediawiki/docroot/mediawiki.org/beacon/event/index.php(56)
#0[internal function]MWExceptionHandler::handleError(int, string, string, int)
#1/srv/mediawiki/docroot/mediawiki.org/beacon/event/index.php(56)trigger_error(string, int)
#2{main}
Impact
Notes

^ Warnings do still appear in the logs...

Hm, okay.

Should they not? Should I log this at DEBUG level then? Is it happening a lot?

This is really a bad client doing something they shouldn't. Maybe it is good to have these in the logs?

Like most logging, it all depends if anyone is going to do anything with them.

If we don't care, probably they shouldn't be in the logs.

If we do care, whether there's something we can do directly, or not... That should really be the followup.

The errors obviously come from (at least in part, or maybe completely from?) TemplateData, and look to be code from rETDA415286e377a4: Send metrics for template property interactions for T260343: Collect on-going numbers related to TemplateData editor dialog use. Seemingly directly from edits on mediawiki.org - https://www.mediawiki.org/w/index.php?title=Template:Speedy/doc&action=edit&templatedata=edit etc

The Metrics.js file originally comes from rETDAd8e418671d98: Send metrics when opening the dialog T260343: Collect on-going numbers related to TemplateData editor dialog use.

Should this logging/instrumentation be turned off? Is WMDE still caring/collecting/expecting this data/logging to be appearing etc?

Thank you for the digging.

The TemplateDataEditor instrumentation was migrated in 2021.
https://gerrit.wikimedia.org/r/c/mediawiki/extensions/TemplateData/+/666674

I suspect (T383939#10502196) the client (maybe not even WMF) logging this data is using some old installed version of mediawiki/extensions/TemplateData.

So, yes, the client should stop doing this, but I am not sure if we have control of the offending client.

While it's possible they're faking the referrer... This kinda feels unlikely....

There's been no edits on https://www.mediawiki.org/w/index.php?title=Template:Speedy/doc&action=history, and certainly playing around on it doesn't seem to trigger anything. I was going to try mwgrep (but T384764: mwgrep cannot be used from a deployment host) to see if for some bizarre reason someone had copied something into their user JS, but seems unlikely.

That the migration happened in 2021, feels unlikely that ~4 years later, that it could be some weird JS cache, even on some sort of mirror of mediawiki.org

I suspect (T383939#10502196) the client (maybe not even WMF) logging this data is using some old installed version of mediawiki/extensions/TemplateData.

Whats the IP(s) etc? Feel free to DM me on whatever rather than disclosing on the task.

Whats the IP(s) etc? Feel free to DM me on whatever rather than disclosing on the task.

Here is a link to a saved superset query with results.

https://superset.wikimedia.org/sqllab/?savedQueryId=1035

In case you explore more:

  • Since this queries large webrequest data via presto, keep the WHERE date fields limited to a single hour at a time.
  • Note that there are some uri_hosts other than mediawiki.org. That means that these bad client requests do go to other wikis, but we aren't logging those, since this /beacon/event/index.php endpoint is only available on mediawiki.org.

Screenshot 2025-03-10 at 15.34.00.png (277×962 px, 50 KB)

Weirdly on numerous wikis too...

The TemplateDataEditor instrumentation was migrated in 2021.
https://gerrit.wikimedia.org/r/c/mediawiki/extensions/TemplateData/+/666674

I suspect (T383939#10502196) the client (maybe not even WMF) logging this data is using some old installed version of mediawiki/extensions/TemplateData.

From a quick look... This should be included in all MW versions at least as far back as REL1_36.. Making this all the more weird.

Screenshot 2025-03-10 at 17.13.17.png (289×890 px, 86 KB)

Even more weird... 17619658, if it's genuine is ATripathi-WMF...

And seem to correlate with some edits on meta...

Screenshot 2025-03-10 at 17.14.16.png (581×1 px, 238 KB)

@awight Any ideas on all of this?

Should the logging be for all users? Or is there some limiting/filtering...

I'm not exactly sure what needs doing here.

Yes, the logging was for all users. The assumption was that not so many users interact with the template dialog in VisualEditor anyway. So we wanted to log all of them.

No, the TechWish team is not using these numbers for anything at the moment. The project is finished and considered a success for quite a while now. Please feel free to disable or possibly even drop the TemplateDataEditor logging if that helps.

Cheers.

If no one is using these numbers, we should definitely look at cleaning it up.

There's currently no config variable or otherwise for disabling it on the extension side AFAIK (to stop it doing the calls), so maybe lets just strip it out, and then do whatever extra undeploy work is necessary...

Change #1126130 had a related patch set uploaded (by Reedy; author: Reedy):

[mediawiki/extensions/TemplateData@master] Drop tracking metrics

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

Sure, thanks! Please give us a few hours. I will ask around in the team tomorrow morning and then merge your patch(es).

Change #1126133 had a related patch set uploaded (by Reedy; author: Reedy):

[mediawiki/extensions/TemplateData@master] Drop more EventLogging

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

Could the two TemplateData patches get a review, please? Thanks a lot!

We pinged the Community-Tech team two weeks ago as they are currently actively working on the TemplateData extension and might be interested in this. They responded and wanted to ask around. We are still waiting for a decision. Personally I think we can consider this a silent agreement after two weeks and continue to remove the code. But I am not 100% sure. Maybe you need to ping them again?

WMDE-TechWish is fine with removing all this tracking code. The two patches are ready to be merged.

Change #1126130 merged by jenkins-bot:

[mediawiki/extensions/TemplateData@master] Drop tracking metrics

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

Change #1126133 merged by jenkins-bot:

[mediawiki/extensions/TemplateData@master] Drop more EventLogging

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