Page MenuHomePhabricator

`mediawiki.api-request` validation errors from Extension:OAuth `context.oauth_consumer_*` logging context
Closed, ResolvedPublic

Description

Summary

EventGate is rejecting mediawiki.api-request events with schema ValidationErrors because Extension:OAuth adds four context.oauth_consumer_* fields to MediaWiki's global logging context, which are then flattened onto the api-request event as unknown top-level properties. The schema /mediawiki/api/request/1.0.0 is additionalProperties: false, so every affected event is dropped.

This is the same failure mode as T411074 (context.ab_tests), now recurring with a different context.* field. T411074 was fixed by removing the field from the logging context and explicitly deferred "the correct fix".

These fields were added in https://gerrit.wikimedia.org/r/c/mediawiki/extensions/OAuth/+/1308180

Impact

  • Continuous loss of mediawiki.api-request events for OAuth-authenticated requests (e.g. bots such as InternetArchiveBot). Rejected events are diverted to eventgate-analytics.error.validation and never reach the primary stream / Hadoop.
  • Steady rate ~0.3–0.5 errors/s on eqiad, with bursts to ~3.7/s during OAuth-bot activity.
  • Fires the EventgateValidationErrors critical alert (data-engineering) whenever a burst pushes the 15m rate over the eventgate-analytics threshold of 1/s.
  • From my understanding, if the change is going out with the deployment train, it will roll out to more wikis this week and may cause more validation errors and alerts.

Timeline (UTC)

  • 2026-07-28 ~18:45 — onset, step to sustained ~0.45/s (eqiad only). Correlates with an OAuth-extension rollout — to confirm against SAL / train.
  • 2026-07-29 00:05–00:10 — burst to ~3.7/s (OAuth-bot traffic); 15m rate crosses >1/s.
  • 2026-07-29 00:06EventgateValidationErrors critical fires.
  • 2026-07-29 ~00:15 — burst subsides; rate returns to ~0.3/s baseline; alert auto-resolves
  • Ongoing — baseline ~0.3/s still present as of 02:30.

Evidence

Rejected event (from eventgate-analytics.error.validation, schema /error/2.1.0):

error_type:          ValidationError
errored_schema_uri:  /mediawiki/api/request/1.0.0
errored_stream_name: mediawiki.api-request
message:             '' should NOT have additional properties (x4)

The offending event carried four flat, dotted top-level keys:

"context.oauth_consumer_id":      "562",
"context.oauth_consumer_key":     "ad8e33572688dd300d2b726bee409f5d",
"context.oauth_consumer_name":    "InternetArchiveBot AUTH v2",
"context.oauth_consumer_version": "1.0"

Each unknown property produces one '' should NOT have additional properties ('' = root).

Root cause

Extension:OAuth src/SessionProvider.php, sessionWasAttachedToRequest():

LoggerFactory::getContext()->add( [
    'context.oauth_consumer_id'      => (string)$consumer->getId(),
    'context.oauth_consumer_key'     => $consumer->getConsumerKey(),
    'context.oauth_consumer_name'    => $consumer->getName(),
    'context.oauth_consumer_version' => $consumer->getVersion(),
] );

This adds the fields to the global request logging context so they appear in Logstash. Per T411074, the api-request Monolog channel has an eventbus logger, so the entire logging context is injected into the event sent to EventGate (call chain: ApiMain::logRequest() -> wfDebugLog('api-request', ...) -> Monolog ContextProcessor -> LoggingContext::get()). The keys are copied verbatim as flat dotted top-level properties; the closed schema rejects them.

Solution

  • If we want this data in data lake, the schema should be evolved
  • If not, these fields may need to be moved elsewhere; OR the fields should be filtered out

References

Event Timeline

Restricted Application added subscribers: Cyberpower678, Aklapper. · View Herald Transcript

These fields are being added by Monolog's ContextProcessor. Loggers which need to have an exact set of fields should probably control what processors they are using.

Milimetric triaged this task as High priority.
Milimetric subscribed.

@AKhatun_WMF can you triage by:

  • assign to schema owner
  • find someone on DPE to assist with any changes

This is not the first time this has happened, but I'm surprised this hasn't happened more often. mediawiki.api_request and the EventBus monolog integration have been around for a LONG time. I guess it is rare than anyone has added context fields to these logs, and that is because usually doing so would require editing ApiMain.php.

I don't think there is an owner of this stream, but it is used by many things.

These fields are being added by Monolog's ContextProcessor. Loggers which need to have an exact set of fields should probably control what processors they are using.

This is being logged via the api-request channel configured by wmgMonologChannels.

Is it possible to tell logs going through the api-request channel to not use the ContextProcessor?

I don't think evolving the schema to add these fields is the correct thing to do. We will never be able to keep up with fields that can be injected into log context by any code.

So, we need some way to avoid emitting them. Unless there is some slick way to know which fields were explicitly set in $logCtx param to wmfDebugLog and then remove them, EventBusMonologAdapter should probably just explicitly set the fields it expects to be in the schema.

I don't think there is an owner of this stream, but it is used by many things.

The owner should probably be the MediaWiki-API-Platform-Team ... this is Action API instrumentation ;)

EventBusMonologAdapter should probably just explicitly set the fields it expects to be in the schema.

Ergh, but EventBusMonologAdapter is not a mediawiki.api_request request specific adapter. ...How did this ever work?

...How did this ever work?

Oh, EventBusMonologAdapter just expects that context IS the event, including the stream name and $schema the event should use. So variable log context works fine, as long as the logging context is never modified globally. EventBusMonologAdapter expects the logging call to set the logCtx fully.

So yes, we need something that avoids the ContextProcessor added fields somehow.

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

[mediawiki/extensions/EventBus@master] Monolog: Strip global logging context from EventBus events

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

Welp. Thank you Claude.

Patch submitted.

Is it possible to tell logs going through the api-request channel to not use the ContextProcessor?

Not straightforwardly, it seems, because EventBus is set up as a separate handler but not as a separate logger, so by the time the handler code is invoked, the processors have already run.

(And the processors are added unconditionally right now.)

Unless there is some slick way to know which fields were explicitly set in $logCtx param to wmfDebugLog and then remove them, EventBusMonologAdapter should probably just explicitly set the fields it expects to be in the schema.

By convention, context fields start with context.. That said, a log handler requiring a strict schema is probably better off using that schema explicitly to filter the data.

By convention, context fields start with context.

There seem to be two ways that context.* fields can be set. By wfDebugLog call ($logCtx param), and by ContextProcessors that are injecting more data later.

It looks like EventBusMonologAdapter was not expecting the latter to happen.

a log handler requiring a strict schema is probably better off using that schema explicitly to filter the data.

I'm looking for a fix that will be quick to fix the problem now, without having to talk about ownership of api-request and other logs, and what we should do with EventBusMonologAdapter. If we had time, I'd say ApiMain should emit an ApiRequestEvent DomainEvent, and a listener would just produce this event data.

I don't have time to fix ApiMain, so...any other suggestions?

@Ottomata should we get MediaWiki-API-Platform-Team involved, or any other team? The group-2 deployment tomorrow may cause even more damage.

Ya I'm not sure. @Tgr -1ed the patch, but I don't have a better idea atm...

Do you all want me to rollback to group0?

Given the un-readiness of the patch and the rate of errors, I am going to roll back.

Mentioned in SAL (#wikimedia-operations) [2026-07-29T19:11:24Z] <dduvall> rolling back wmf.13 to group0 due to T433457 (cc T430832)

Yes, thank you! We don't have a solution yet, and need to get more people on board.

Perhaps https://gerrit.wikimedia.org/r/c/mediawiki/extensions/OAuth/+/1308180 should be reverted until we solve the EventBusMonoLogAdapter problem?

I would suggest storing only the expected fields into mediawiki.api-request, instead of the entire log event. The log fields are not a stable API and can change. If you can, use a hook or a domain event, since those are documented and stable.

I would suggest storing only the expected fields into mediawiki.api-request, instead of the entire log event. The log fields are not a stable API and can change. If you can, use a hook or a domain event, since those are documented and stable.

Yes, I agree that is a nicer long term solution. This EventBusMonologAdapter was created long ago to handle Action API Request events (and possibly other?) events. This usage does not currently have an owner.

I don't want to implement a long term solution to fix a train blocker.

Very open to other suggestions!

I don't really see that as a long-term solution. In the longer term maybe someone should replace EventBusMonologHandler entirely with some hooks or domain events. But, while it exists, it needs to not send incorrect events, right? I suppose you could also silence the validation errors somehow, if there is a reason not to fix them.

Change #1319163 had a related patch set uploaded (by Gergő Tisza; author: Gergő Tisza):

[mediawiki/extensions/EventBus@master] Monolog: Strip diagnostic context from Monolog-based EventBus events

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

But, while it exists, it needs to not send incorrect events, right?

It sends events yes, but it does so by sending the $logCtx as the event itself. It has no knowledge of the mediawiki/api/request schema, and I don't think we should hardcode it to do so.

There were other log channels that used this (there is still a cirrussearch-request channel), but I'm not sure what is actually flowing through this anymore.

Gergo is patching...

		foreach ( $record['context'] as $key => $value ) {
			if ( !str_starts_with( $key, 'context.' ) ) {

Apparently I missed that 'starts with context.*' meant the actually string key was 'context.___', not that the key in the $record all started with context.

I guess $logCtx is $record['context'], and things added by ContextProcessor are $record['context']['context.*']?

Sorry, did not realize this was a train blocker.

There seem to be two ways that context.* fields can be set. By wfDebugLog call ($logCtx param), and by ContextProcessors that are injecting more data later.

"Context" is an overloaded term, technically all the data in the log event is part of the log context, ContextProcessor adds global context (maybe it should have been named GlobalContextProcessor, and maybe global. would have been a better prefix... oh well). The context. prefix is only used by ContextProcessor (or rather, by callers of LoggingContext::add(); it's just a convention).

Change #1319106 abandoned by Ottomata:

[mediawiki/extensions/EventBus@master] Monolog: Strip global logging context from EventBus events

Reason:

in favor of I3c23a5eebddecdbd4aa449771e0ea49034376eb1

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

Change #1319163 merged by jenkins-bot:

[mediawiki/extensions/EventBus@master] Monolog: Strip diagnostic context from Monolog-based EventBus events

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

Change #1319489 had a related patch set uploaded (by Jforrester; author: Gergő Tisza):

[mediawiki/extensions/EventBus@wmf/1.47.0-wmf.13] Monolog: Strip diagnostic context from Monolog-based EventBus events

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

Change #1319489 merged by jenkins-bot:

[mediawiki/extensions/EventBus@wmf/1.47.0-wmf.13] Monolog: Strip diagnostic context from Monolog-based EventBus events

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

Mentioned in SAL (#wikimedia-operations) [2026-07-30T14:45:00Z] <tchin@deploy1003> Started scap sync-world: Backport for [[gerrit:1319489|Monolog: Strip diagnostic context from Monolog-based EventBus events (T433457)]]

Mentioned in SAL (#wikimedia-operations) [2026-07-30T14:46:59Z] <tchin@deploy1003> jforrester, tchin: Backport for [[gerrit:1319489|Monolog: Strip diagnostic context from Monolog-based EventBus events (T433457)]] synced to the testservers (see https://wikitech.wikimedia.org/wiki/Mwdebug). Changes can now be verified there.

Mentioned in SAL (#wikimedia-operations) [2026-07-30T14:51:48Z] <tchin@deploy1003> Finished scap sync-world: Backport for [[gerrit:1319489|Monolog: Strip diagnostic context from Monolog-based EventBus events (T433457)]] (duration: 06m 48s)

Fix has been deployed to 1.47.0-wmf.13 (thank you @tchin!) Monitoring existing group 0 error rates. If errors remain down we can unblock train and ship to rest of the groups.

Jdforrester-WMF raised the priority of this task from High to Unbreak Now!.Thu, Jul 30, 2:59 PM
Jdforrester-WMF subscribed.

(Train blockers should always be marked UBN, per policy.)

Over to @dduvall to decide whether to roll the train (my preference), or (given how late in the week we are) to give up entirely and just roll this out in wmf.14.

Screenshot 2026-07-30 at 11.14.13 AM.png (2,826×1,556 px, 307 KB)

https://grafana.wikimedia.org/goto/bftojviexfxfkd?orgId=default
Error is down to 0! Will continue to monitor. Looks good so far.

Thanks all! I will roll the train.

dduvall lowered the priority of this task from Unbreak Now! to Medium.Thu, Jul 30, 6:22 PM

I don't see any errors following group1 deployment. Deescalating and I'll leave resolution status to y'all.