We should check logs once rEGRE9f3d06d44d3e447d8137631c8999acda310798fb reaches production to hopefully get additional data in the log. So far I haven't seen any log of this in beta, but I'm not a great filterer and unfamiliar with beta logstash.

I’m trying to figure out why we’re not getting the additional error log implemented in 1142597: fix(logging): temporary subscribe to analytics uncaught errors. I can reliably reproduce the error by running mw.track('stats.mediawiki_GrowthExperiments_suggested_edits_tti_seconds', NaN ) in the JS console. The first error is correctly logged (statsd handles it) and I can see our additional log code executed, but for some reason the second mw.errorLogger.logError( seems dismissed. Some of my current hypothesis are:

• The additional properties we're adding to error_context are not compliant with the schema for some reason. Although my understanding from mediawiki/client/error/2.0.0.yaml#L21 is that we can add arbitrary data. Maybe the camel case vs underscore case?
• mw.errorLog.log does some kind of optimization and interprets the second error as already logged because of similarity with the prior (?) Or because it is fired very short time after another?

In my debugging checks I found the mw.errorLogger state to be "firing" while trying to process the additional log and not triggering it (although the debug session may be changing the conditions of execution).

Ideas are welcome, cc @Cyndymediawiksim @Michael @Urbanecm_WMF

In T394289#10825729, @Sgs wrote:

• The additional properties we're adding to error_context are not compliant with the schema for some reason. Although my understanding from mediawiki/client/error/2.0.0.yaml#L21 is that we can add arbitrary data. Maybe the camel case vs underscore case?

We can add arbitrary strings. The current implementation logs numbers instead. For this reason, the event is refused by the validation service:

'.error_context['serverDuration']' should be string, '.error_context['GEHomepageStartTime']' should be string

Fortunately, the validation errors include the actual event. But, we should either fix the patch or remove the extra data altogether.

Hope this helps!

Change #1147720 had a related patch set uploaded (by Sergio Gimeno; author: Sergio Gimeno):

[mediawiki/extensions/GrowthExperiments@master] stats(SuggestedEdits): avoid tracking negative tti durations

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

In T394289#10833569, @Urbanecm_WMF wrote:

We can add arbitrary strings. The current implementation logs numbers instead. For this reason, the event is refused by the validation service:

Gotcha.

Hope this helps!

It does indeed, ty. I've submitted a patch to avoid sending negative integers to stats, I'm keeping the additional logging for now with stringified values in case the are other sources for invalid timings.

In T394289#10833569, @Urbanecm_WMF wrote:

In T394289#10825729, @Sgs wrote:

• The additional properties we're adding to error_context are not compliant with the schema for some reason. Although my understanding from mediawiki/client/error/2.0.0.yaml#L21 is that we can add arbitrary data. Maybe the camel case vs underscore case?

We can add arbitrary strings. The current implementation logs numbers instead. For this reason, the event is refused by the validation service:

'.error_context['serverDuration']' should be string, '.error_context['GEHomepageStartTime']' should be string

Where do you see these errors from the validation service?

Fortunately, the validation errors include the actual event. But, we should either fix the patch or remove the extra data altogether.

Could you point me to where the actual event is included? I'm not seeing it in logstash: https://logstash.wikimedia.org/app/discover#/doc/logstash-*/logstash-default-1-7.0.0-1-2025.05.20?id=I_6x7JYB-jfKnJise96Y

Change #1147720 merged by jenkins-bot:

[mediawiki/extensions/GrowthExperiments@master] stats(SuggestedEdits): avoid tracking negative tti durations

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

Change #1149345 had a related patch set uploaded (by Michael Große; author: Sergio Gimeno):

[mediawiki/extensions/GrowthExperiments@wmf/1.45.0-wmf.2] stats(SuggestedEdits): avoid tracking negative tti durations

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

Change #1149345 merged by jenkins-bot:

[mediawiki/extensions/GrowthExperiments@wmf/1.45.0-wmf.2] stats(SuggestedEdits): avoid tracking negative tti durations

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

Mentioned in SAL (#wikimedia-operations) [2025-05-22T13:58:09Z] <sbisson@deploy1003> Started scap sync-world: Backport for [[gerrit:1149345|stats(SuggestedEdits): avoid tracking negative tti durations (T394289 T394701)]]

Mentioned in SAL (#wikimedia-operations) [2025-05-22T14:00:25Z] <sbisson@deploy1003> sbisson, migr: Backport for [[gerrit:1149345|stats(SuggestedEdits): avoid tracking negative tti durations (T394289 T394701)]] synced to the testservers (see https://wikitech.wikimedia.org/wiki/Mwdebug). Changes can now be verified there.

Mentioned in SAL (#wikimedia-operations) [2025-05-22T14:09:13Z] <sbisson@deploy1003> Finished scap sync-world: Backport for [[gerrit:1149345|stats(SuggestedEdits): avoid tracking negative tti durations (T394289 T394701)]] (duration: 11m 04s)