2021427 - Intermittent devtools/client/netmonitor/test/browser_net_duration-sort.js | single tracking bug

Status: RESOLVED FIXED

(DevTools :: Netmonitor, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: sstanca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=552107377&repo=autoland&task=B_1zixRzQYeLtxTzb7UKHQ.0
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/B_1zixRzQYeLtxTzb7UKHQ/runs/0/artifacts/public/logs/live_backing.log

---

[task 2026-03-05T19:29:02.099+00:00] 19:29:02     INFO - TEST-PASS | devtools/client/netmonitor/test/browser_net_domain-not-found.js | took 5264ms
[task 2026-03-05T19:29:02.223+00:00] 19:29:02     INFO - TEST-START | devtools/client/netmonitor/test/browser_net_duration-sort.js
[task 2026-03-05T19:29:05.101+00:00] 19:29:05     INFO - GECKO(9080) | console.error: "Unable to find target with innerWindowId:176093659137"
[task 2026-03-05T19:29:07.385+00:00] 19:29:07     INFO -  console.trace: Places - FrecencyRecalculator: "Recalculate 50 frecency values"
[task 2026-03-05T19:29:07.385+00:00] 19:29:07     INFO -  resource://gre/modules/PlacesFrecencyRecalculator.sys.mjs 263 recalculateSomeFrecencies
[task 2026-03-05T19:29:07.385+00:00] 19:29:07     INFO -  resource://gre/modules/PlacesFrecencyRecalculator.sys.mjs 195 #taskFn
[task 2026-03-05T19:29:07.386+00:00] 19:29:07     INFO -  resource://gre/modules/DeferredTask.sys.mjs 412 #runTask
[task 2026-03-05T19:29:07.386+00:00] 19:29:07     INFO -  resource://gre/modules/DeferredTask.sys.mjs 383 #timerCallback/<
[task 2026-03-05T19:29:07.386+00:00] 19:29:07     INFO -  resource://gre/modules/DeferredTask.sys.mjs 402 #timerCallback
[task 2026-03-05T19:29:07.387+00:00] 19:29:07     INFO -  resource://gre/modules/DeferredTask.sys.mjs 229 #startTimer/callback/<
[task 2026-03-05T19:29:07.387+00:00] 19:29:07     INFO -  D:\task_177273806420921\build\tests\mochitest\server.js 178 runServer
[task 2026-03-05T19:29:07.387+00:00] 19:29:07     INFO -  D:\task_177273806420921\build\tests\mochitest\server.js 71
[task 2026-03-05T19:29:07.387+00:00] 19:29:07     INFO -  console.error: (new TypeError("can't access property \"executeTransaction\", db is undefined", "resource://gre/modules/PlacesFrecencyRecalculator.sys.mjs", 269))
[task 2026-03-05T19:29:07.388+00:00] 19:29:07     INFO -  console.error: Places - FrecencyRecalculator: (new TypeError("can't access property \"executeTransaction\", db is undefined", "resource://gre/modules/PlacesFrecencyRecalculator.sys.mjs", 269))
[task 2026-03-05T19:29:07.808+00:00] 19:29:07     INFO - GECKO(9080) | [dump-scope] Serializing variables for frame: chrome://mochikit/content/browser-test.js @ 38:9
[task 2026-03-05T19:29:07.810+00:00] 19:29:07     INFO - GECKO(9080) | [dump-scope] Serializing variables for frame: chrome://mochikit/content/browser-test.js @ 1882:3
[task 2026-03-05T19:29:07.811+00:00] 19:29:07     INFO - GECKO(9080) | [dump-scope] Serializing variables for frame: chrome://mochikit/content/browser-test.js @ 1920:9
[task 2026-03-05T19:29:07.811+00:00] 19:29:07     INFO - GECKO(9080) | [dump-scope] Serializing variables for frame: chrome://mochikit/content/browser-test.js @ 1931:10
[task 2026-03-05T19:29:07.812+00:00] 19:29:07     INFO - GECKO(9080) | [dump-scope] Serializing variables for frame: chrome://mochitests/content/browser/devtools/client/netmonitor/test/browser_net_duration-sort.js @ 107:7
[task 2026-03-05T19:29:07.813+00:00] 19:29:07     INFO - GECKO(9080) | [dump-scope] Serializing variables for frame: chrome://mochitests/content/browser/devtools/client/netmonitor/test/browser_net_duration-sort.js @ 39:9
[task 2026-03-05T19:29:07.849+00:00] 19:29:07     INFO - GECKO(9080) | [dump-scope] Serializing variables for frame: chrome://mochikit/content/browser-test.js @ 1394:26
[task 2026-03-05T19:29:07.850+00:00] 19:29:07     INFO - GECKO(9080) | [dump-scope] Serializing variables for frame: chrome://mochikit/content/browser-test.js @ 1484:18
[task 2026-03-05T19:29:07.857+00:00] 19:29:07     INFO - GECKO(9080) | [dump-scope] Saving scope variables as a JSON file: D:\task_177273806420921\build\blobber_upload_dir\scope-variables-1772738947856-browser_net_duration-sort.js_39_9.json
[task 2026-03-05T19:29:07.861+00:00] 19:29:07     INFO - TEST-INFO | started process screenshot
[task 2026-03-05T19:29:08.081+00:00] 19:29:08     INFO - TEST-INFO | screenshot: exit 0
[task 2026-03-05T19:29:08.089+00:00] 19:29:08     INFO - Buffered messages logged at 19:29:02
[task 2026-03-05T19:29:08.090+00:00] 19:29:08     INFO - Entering setup bound 
[task 2026-03-05T19:29:08.091+00:00] 19:29:08     INFO - Leaving setup bound 
[task 2026-03-05T19:29:08.091+00:00] 19:29:08     INFO - Entering test 
[task 2026-03-05T19:29:08.092+00:00] 19:29:08     INFO - Initializing a network monitor pane.
[task 2026-03-05T19:29:08.092+00:00] 19:29:08     INFO - Adding a new tab with URL: https://example.com/browser/devtools/client/netmonitor/test/html_simple-test-page.html
[task 2026-03-05T19:29:08.093+00:00] 19:29:08     INFO - Buffered messages logged at 19:29:03
[task 2026-03-05T19:29:08.093+00:00] 19:29:08     INFO - Tab added and finished loading
[task 2026-03-05T19:29:08.094+00:00] 19:29:08     INFO - Net tab added successfully: https://example.com/browser/devtools/client/netmonitor/test/html_simple-test-page.html
[task 2026-03-05T19:29:08.095+00:00] 19:29:08     INFO - Buffered messages logged at 19:29:04
[task 2026-03-05T19:29:08.096+00:00] 19:29:08     INFO - Network monitor pane shown successfully.
[task 2026-03-05T19:29:08.097+00:00] 19:29:08     INFO - Disabling cache and reloading page.
[task 2026-03-05T19:29:08.099+00:00] 19:29:08     INFO - > Network event progress: NetworkEvent: 1/1, PayloadReady: 0/1, EventTimings: 0/1, got NetMonitor:NetworkEvent for server0.conn0.netEvent8
[task 2026-03-05T19:29:08.099+00:00] 19:29:08     INFO - Buffered messages logged at 19:29:05
[task 2026-03-05T19:29:08.100+00:00] 19:29:08     INFO - Got marker: dom-interactive
[task 2026-03-05T19:29:08.103+00:00] 19:29:08     INFO - Got marker: dom-complete
[task 2026-03-05T19:29:08.104+00:00] 19:29:08     INFO - Got two timeline markers, done waiting
[task 2026-03-05T19:29:08.105+00:00] 19:29:08     INFO - > Network event progress: NetworkEvent: 1/1, PayloadReady: 1/1, EventTimings: 0/1, got NetMonitor:PayloadReady for server0.conn0.netEvent8
[task 2026-03-05T19:29:08.106+00:00] 19:29:08     INFO - > Network event progress: NetworkEvent: 1/1, PayloadReady: 1/1, EventTimings: 1/1, got NetMonitor:NetworkEventUpdated:EventTimings for server0.conn0.netEvent8
[task 2026-03-05T19:29:08.106+00:00] 19:29:08     INFO - Wait for completion of all NetworkUpdateEvents packets...
[task 2026-03-05T19:29:08.107+00:00] 19:29:08     INFO - Clearing the network requests in the UI
[task 2026-03-05T19:29:08.108+00:00] 19:29:08     INFO - Starting test... 
[task 2026-03-05T19:29:08.108+00:00] 19:29:08     INFO - Sending initial requests.
[task 2026-03-05T19:29:08.109+00:00] 19:29:08     INFO - > Network event progress: NetworkEvent: 1/3, PayloadReady: 0/3, EventTimings: 0/1, got NetMonitor:NetworkEvent for server0.conn0.netEvent10
[task 2026-03-05T19:29:08.110+00:00] 19:29:08     INFO - > Network event progress: NetworkEvent: 2/3, PayloadReady: 0/3, EventTimings: 0/2, got NetMonitor:NetworkEvent for server0.conn0.netEvent11
[task 2026-03-05T19:29:08.110+00:00] 19:29:08     INFO - > Network event progress: NetworkEvent: 3/3, PayloadReady: 0/3, EventTimings: 0/3, got NetMonitor:NetworkEvent for server0.conn0.netEvent12
[task 2026-03-05T19:29:08.111+00:00] 19:29:08     INFO - Buffered messages logged at 19:29:07
[task 2026-03-05T19:29:08.112+00:00] 19:29:08     INFO - > Network event progress: NetworkEvent: 3/3, PayloadReady: 1/3, EventTimings: 0/3, got NetMonitor:PayloadReady for server0.conn0.netEvent10
[task 2026-03-05T19:29:08.113+00:00] 19:29:08     INFO - > Network event progress: NetworkEvent: 3/3, PayloadReady: 2/3, EventTimings: 0/3, got NetMonitor:PayloadReady for server0.conn0.netEvent11
[task 2026-03-05T19:29:08.113+00:00] 19:29:08     INFO - > Network event progress: NetworkEvent: 3/3, PayloadReady: 3/3, EventTimings: 0/3, got NetMonitor:PayloadReady for server0.conn0.netEvent12
[task 2026-03-05T19:29:08.114+00:00] 19:29:08     INFO - > Network event progress: NetworkEvent: 3/3, PayloadReady: 3/3, EventTimings: 1/3, got NetMonitor:NetworkEventUpdated:EventTimings for server0.conn0.netEvent10
[task 2026-03-05T19:29:08.115+00:00] 19:29:08     INFO - > Network event progress: NetworkEvent: 3/3, PayloadReady: 3/3, EventTimings: 2/3, got NetMonitor:NetworkEventUpdated:EventTimings for server0.conn0.netEvent11
[task 2026-03-05T19:29:08.116+00:00] 19:29:08     INFO - > Network event progress: NetworkEvent: 3/3, PayloadReady: 3/3, EventTimings: 3/3, got NetMonitor:NetworkEventUpdated:EventTimings for server0.conn0.netEvent12
[task 2026-03-05T19:29:08.116+00:00] 19:29:08     INFO - Testing initial items duration sort, ascending.
[task 2026-03-05T19:29:08.117+00:00] 19:29:08     INFO - Buffered messages finished
[task 2026-03-05T19:29:08.119+00:00] 19:29:08     INFO - TEST-UNEXPECTED-FAIL | devtools/client/netmonitor/test/browser_net_duration-sort.js | 50ms request sorted correctly. - Got "https://example.com/browser/devtools/client/netmonitor/test/sjs_delay-test-server.sjs?delay=1500", expected "https://example.com/browser/devtools/client/netmonitor/test/sjs_delay-test-server.sjs?delay=50"
[task 2026-03-05T19:29:08.119+00:00] 19:29:08     INFO - chrome://mochikit/content/browser-test.js:test_is:1931
[task 2026-03-05T19:29:08.119+00:00] 19:29:08     INFO - chrome://mochitests/content/browser/devtools/client/netmonitor/test/browser_net_duration-sort.js:testInitialContents:107
[task 2026-03-05T19:29:08.119+00:00] 19:29:08     INFO - chrome://mochitests/content/browser/devtools/client/netmonitor/test/browser_net_duration-sort.js:null:39
[task 2026-03-05T19:29:08.119+00:00] 19:29:08     INFO - chrome://mochikit/content/browser-test.js:handleTask:1394
[task 2026-03-05T19:29:08.119+00:00] 19:29:08     INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1484
[task 2026-03-05T19:29:08.119+00:00] 19:29:08     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1635
[task 2026-03-05T19:29:08.119+00:00] 19:29:08     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1374
[task 2026-03-05T19:29:08.119+00:00] 19:29:08     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1063
[task 2026-03-05T19:29:08.120+00:00] 19:29:08     INFO - TEST-PASS | devtools/client/netmonitor/test/browser_net_duration-sort.js | 500ms request sorted correctly.

Comment 1

[Intermittent Failures Robot]

15 failures were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 8
• mozilla-central: 6
• try: 1

Table

	cf	no_variant
windows11-x86_64/asan	1	3
windows11-x86_64/ccov	1	2
windows11-x86_64/debug		8

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=2021427&startday=2026-03-02&endday=2026-03-08&tree=all

Comment 2

[Julian Descottes [:jdescottes]]

Windows only, mostly slow platforms. The requests seem out of order compared to the expectation.

Comment 3

[Intermittent Failures Robot]

30 failures were associated with this bug in the last 7 days.

This failure happened more than 30 times this week! Resolving this bug is a high priority.

Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled.

Repository breakdown:

• autoland: 19
• try: 2
• mozilla-central: 9

Table

	no_variant
windows11-x86_64/asan	5
windows11-x86_64/ccov	2
windows11-x86_64/debug	23

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=2021427&startday=2026-03-09&endday=2026-03-15&tree=all

Comment 4

[Julian Descottes [:jdescottes]]

Looking at failure screenshots, all requests seem to be delayed, sometimes up to 10 seconds. And the delay coming from our test server is seems to be "merged" with the overall delay for the requests.

I'm not sure if the issue is on the necko side, or on the test server side. I was also unable to verify the issue in "test-verify".
With buffered logs it's a bit hard to tell, but it does seem like the payloads are received late and out of order.

One thing to investigate is to revert Bug 2020268 to see if that helps - but I need to reproduce on Try first.

We might just disable on windows for now, this is not a devtools issue.

Comment 5

[Julian Descottes [:jdescottes]]

Attachment: Bug 2021427 - [devtools] Skip browser_net_duration-sort.js on windows non-opt builds

Comment 6

[Julian Descottes [:jdescottes]]

Preparing a patch to disable, but let's wait for try results still:

• baseline netmonitor toml run https://treeherder.mozilla.org/jobs?repo=try&revision=cc649b8d5bc1bc97593c7f7fb1a35511ebb0a93b
• revert bug 2020268 netmonitor toml run https://treeherder.mozilla.org/jobs?repo=try&selectedTaskRun=PP5rITfhTe6zZZpUTdwd-g.0&revision=1600bdfb13a433e8617d643260492b12200dde66

Mostly looking forward to the debug/asan results here.

Comment 7

[Julian Descottes [:jdescottes]]

Nothing clear on try, for now let's disable

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://github.com/mozilla-firefox/firefox/commit/608aff5c6bc4
https://hg.mozilla.org/integration/autoland/rev/b0a568a478d3
[devtools] Skip browser_net_duration-sort.js on windows non-opt builds r=devtools-reviewers,bomsy

Comment 9

[Cristian Tuns]

https://hg.mozilla.org/mozilla-central/rev/b0a568a478d3

Comment 10

[Intermittent Failures Robot]

11 failures were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 8
• mozilla-central: 2
• try: 1

Table

	no_variant
windows11-x86_64/asan	1
windows11-x86_64/ccov	1
windows11-x86_64/debug	9

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=2021427&startday=2026-03-16&endday=2026-03-22&tree=all