initSuggestedTasks: server duration is negative error
Open, In Progress, MediumPublic2 Estimated Story PointsPRODUCTION ERROR
Actions

Assigned To

None

Authored By

	Etonkovidova
	May 29 2025, 10:11 PM

Description

T394289: Invalid timing value for mediawiki_GrowthExperiments_suggested_edits_server_tti_seconds

30-day report on the error - https://logstash.wikimedia.org/goto/db4552a927cc66c919b290b486185892

Error

https://logstash.wikimedia.org/goto/eb91e1daaaa5a8dbce558c503c9fa411

$schema	/mediawiki/client/error/2.0.0
`@timestamp`	May 29, 2025 @ 21:51:14.234
error_context.GEHomepageStartTime	1748555472388
error_context.GEHomepageStartTimeType	number
error_context.component	growthexperiments
error_context.serverDuration	-14390.39990234375
error_context.serverDurationType	number
error_context.special_page	Homepage
error_context.version	1.45.0-wmf.3
error_context.wiki	eswiki
file_url	https://es.wikipedia.org/w/load.php?lang=es&modules=%40wikimedia%2Fcodex%2Ccodex-styles%2Cjquery%2Cmoment%2Coojs-ui-core%2Cvue%7Cext.growthExperiments.Homepage.Impact%2CSuggestedEdits&skin=vector-2022&version=1mqrr
level	ERROR
message	initSuggestedTasks: server duration is negative [Additional data]
meta.domain	es.wikipedia.org
meta.dt	2025-05-29T21:51:13.365Z
meta.id	61d389e2-ebbc-4f79-842b-81937b4c75aa
meta.request_id	b237edb5-cfd3-46d5-b225-10ebe60a191e
meta.stream	mediawiki.client.error
normalized_message	initSuggestedTasks: server duration is negative [Additional data]
stack_trace	at initSuggestedTasks https://es.wikipedia.org/w/load.php lang=es&modules=%40wikimedia%2Fcodex%2Ccodex-styles%2Cjquery%2Cmoment%2Coojs-ui-core%2Cvue%7Cext.growthExperiments.Homepage.Impact%2CSuggestedEdits&skin=vector-2022&version=1mqrr:498:23 at https://es.wikipedia.org/w/load.php?lang=es&modules=%40wikimedia%2Fcodex%2Ccodex styles%2Cjquery%2Cmoment%2Coojs-ui core%2Cvue%7Cext.growthExperiments.Homepage.Impact%2CSuggestedEdits&skin=vector-2022&version=1mqrr:498:603 at index.js https://es.wikipedia.org/w/load.php?lang=es&modules=%40wikimedia%2Fcodex%2Ccodex-styles%2Cjquery%2Cmoment%2Coojs-ui core%2Cvue%7Cext.growthExperiments.Homepage.Impact%2CSuggestedEdits&skin=vector-2022&version=1mqrr:498:893 at runScript https://es.wikipedia.org/w/load.php?lang=es&modules=startup&only=scripts&raw=1&skin=vector-2022:11:748 at Array.<anonymous> https://es.wikipedia.org/w/load.php?lang=es&modules=startup&only=scripts&raw=1&skin=vector 2022:12:504 at flushCssBuffer https://es.wikipedia.org/w/load.php lang=es&modules=startup&only=scripts&raw=1&skin=vector-2022:4:385
type	clienterror
url	https://es.wikipedia.org/wiki/Special:Homepage?title=Especial:P%C3%A1gina_inicial&source=specialwelcomesurvey

Impact

220 errors in 24 hours for wmf.3 - https://logstash.wikimedia.org/goto/65acb821a082add37b2d7868a82ce2d4

Details

Related Changes in Gerrit:

	Subject	Repo	Branch	Lines +/-
	statsd: Improve error logs by adding invalid value	mediawiki/extensions/WikimediaEvents	master	+6 -3
	Replace server-side duration tracking with Performance API	mediawiki/extensions/GrowthExperiments	master	+21 -45

Customize query in gerrit

Related Objects

Mentioned Here: T394289: Invalid timing value for mediawiki_GrowthExperiments_suggested_edits_server_tti_seconds

Event Timeline

Etonkovidova created this task.May 29 2025, 10:11 PM

Restricted Application changed the subtype of this task from "Task" to "Production Error". · View Herald TranscriptMay 29 2025, 10:11 PM

Restricted Application added a subscriber: Aklapper. · View Herald Transcript

Etonkovidova added subscribers: Michael, Sgs, Urbanecm_WMF, Cyndymediawiksim.May 29 2025, 10:12 PM

Pppery added a project: GrowthExperiments.May 29 2025, 10:23 PM

Restricted Application added a project: Growth-Team. · View Herald TranscriptMay 29 2025, 10:23 PM

Our current guess is that this is due to out of sync client devices. Should we completely silent this error, or configure and alarm on spikes?

Etonkovidova updated the task description. (Show Details)Jun 2 2025, 7:01 PM

In T395627#10876436, @Sgs wrote:

Our current guess is that this is due to out of sync client devices. Should we completely silent this error, or configure and alarm on spikes?

Yes, this is the most likely cause. However, what is puzzling

it's reported as Error
the reports started on 2025-05-22
no such reports outside GrowthExperiments context - https://logstash.wikimedia.org/goto/adcdd819bcafac16651eed449d78519f

normalized_message:"initSuggestedTasks: server duration is negative [Additional data]" AND NOT error_context.component:growthexperiments

the rate of reports is still quite high. Last 24 hours - 1,620, https://logstash.wikimedia.org/goto/674813cae5f4ee5c0bc1d82e36232e9a

I wonder if it would make sense to just remove that particular tracking. Maybe adding together a client timestamp and a server timestamp is just a bad idea. While we see the noise in one direction as negative duration errors, the noise in the other direction exists probably just as much.
If we want to include the duration that the request took on the server, then maybe we can make use of some of the early timing marks that the browser provides: https://developer.mozilla.org/en-US/docs/Web/API/PerformanceNavigationTiming

That is, we could replace the servertime with the time the request was started, which would be performance.timeOrigin + performance.getEntriesByType('navigation')[0].requestStart. (see PerformanceResourceTiming/requestStart)

But for now, it seems to me that this composite duration is causing much more problems for us than what we are gaining here, especially given that these things are also already tracked individually.

What do you think?

If we do not want to fix the issue itself, then removing the broken metrics definitely makes sense to me @Michael. Should we repurpose this task to do just that?

Urbanecm_WMF moved this task from Inbox to Triaged on the Growth-Team board.Jul 3 2025, 10:38 AM

This task itself is about fixing the error, and given that it is our most common error on the client by about 1.5 order of magnitude, it makes sense to me to tackle it sooner rather than later:

Above, I outlined both the option of removing it as well as replacing it with a measurement that lives fully in the browser. I'm fine with either. As far as I am concerned, it can be up to the person picking up this task to make that call.

KStoller-WMF set the point value for this task to 2.Jul 21 2025, 4:10 PM

Cyndymediawiksim claimed this task.Jul 22 2025, 12:51 PM

Cyndymediawiksim edited projects, added Growth-Team (Current Sprint); removed Growth-Team.

Cyndymediawiksim changed the task status from Open to In Progress.Jul 22 2025, 1:01 PM

Cyndymediawiksim moved this task from Incoming to Doing on the Growth-Team (Current Sprint) board.

Change #1171579 had a related patch set uploaded (by Cyndywikime; author: Cyndywikime):

[mediawiki/extensions/GrowthExperiments@master] Replace server-side duration tracking with Performance API

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

gerritbot added a project: Patch-For-Review.Jul 22 2025, 1:37 PM

Cyndymediawiksim moved this task from Doing to Code Review on the Growth-Team (Current Sprint) board.Jul 22 2025, 1:54 PM

thcipriani moved this task from Untriaged to Apr-Jun 2025 on the Wikimedia-production-error board.Jul 29 2025, 6:47 PM

Change #1171579 merged by jenkins-bot:

[mediawiki/extensions/GrowthExperiments@master] Replace server-side duration tracking with Performance API

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

ReleaseTaggerBot added a project: MW-1.45-notes (1.45.0-wmf.13; 2025-08-05).Aug 4 2025, 5:00 PM

Maintenance_bot removed a project: Patch-For-Review.Aug 4 2025, 5:36 PM

Cyndymediawiksim moved this task from Code Review to QA on the Growth-Team (Current Sprint) board.Aug 6 2025, 2:32 PM

Checked - the last timestamp for the error Aug 7, 2025 @ 08:38:47.157 - https://logstash.wikimedia.org/goto/025cee5f2c8d6b245f55809350ba523b. ( only for error_context.version: 1.45.0-wmf.12)

For error_context.version: "1.45.0-wmf.14"shows only one error; https://logstash.wikimedia.org/goto/b6a9971eca372006168141b931791579 - querying only Growth specific reports).

In T395627#11084139, @Etonkovidova wrote:

For error_context.version: "1.45.0-wmf.14"shows only one error; https://logstash.wikimedia.org/goto/b6a9971eca372006168141b931791579 - querying only Growth specific reports).

There are now a bunch of those errors. So we re-introduced somehow some issue :/

Let's have another look.

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

[mediawiki/extensions/WikimediaEvents@master] feat: improve statsd error logs by adding invalid value

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

gerritbot added a project: Patch-For-Review.Sep 3 2025, 5:33 PM

Waiting on the above change to be merged and then for it to arrive in production with the train, and then we can better figure out what is going on.

Michael moved this task from Code Review to Blocked / Needs Work on the Growth-Team (Current Sprint) board.Sep 4 2025, 12:14 PM

This is still waiting on code review. It will need some additional follow-up there, but that is currently not a priority for us.

DMburugu edited projects, added Growth Team Maintenance; removed Growth-Team (Maintenance).Oct 8 2025, 11:34 AM

Change #1184569 merged by jenkins-bot:

[mediawiki/extensions/WikimediaEvents@master] statsd: Improve error logs by adding invalid value