1779759 - Intermittent [tier 2] Wd CCOV TEST-UNEXPECTED-TIMEOUT | expected OK (JavaScript error: resource://gre/modules/TerminatorTelemetry.jsm, line 60: AbortError: IOUtils: Shutting down and refusing additional I/O tasks)

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect, P1)

Description

[Treeherder Bug Filer]

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

---

[task 2022-07-15T11:50:05.348Z] 11:50:05     INFO - PID 7844 | 1657885805338	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-07-15T11:50:05.349Z] 11:50:05     INFO - PID 7844 | 1657885805339	webdriver::server	DEBUG	-> GET /session/ae2c9f13-933f-4519-9ddf-c6f94463f4f2/window
[task 2022-07-15T11:50:05.350Z] 11:50:05     INFO - PID 7844 | 1657885805339	Marionette	DEBUG	0 -> [0,153,"WebDriver:GetWindowHandle",{}]
[task 2022-07-15T11:50:05.350Z] 11:50:05     INFO - PID 7844 | 1657885805340	Marionette	DEBUG	0 <- [1,153,null,{"value":"a69b83d4-54fa-4d84-9fbc-a0c42064fa0e"}]
[task 2022-07-15T11:50:05.351Z] 11:50:05     INFO - PID 7844 | 1657885805340	webdriver::server	DEBUG	<- 200 OK {"value":"a69b83d4-54fa-4d84-9fbc-a0c42064fa0e"}
[task 2022-07-15T11:50:05.351Z] 11:50:05     INFO - PID 7844 | 1657885805341	webdriver::server	DEBUG	-> GET /session/ae2c9f13-933f-4519-9ddf-c6f94463f4f2/window/handles
[task 2022-07-15T11:50:05.352Z] 11:50:05     INFO - PID 7844 | 1657885805341	Marionette	DEBUG	0 -> [0,154,"WebDriver:GetWindowHandles",{}]
[task 2022-07-15T11:50:05.353Z] 11:50:05     INFO - PID 7844 | 1657885805341	Marionette	DEBUG	0 <- [1,154,null,["a69b83d4-54fa-4d84-9fbc-a0c42064fa0e"]]
[task 2022-07-15T11:50:05.353Z] 11:50:05     INFO - PID 7844 | 1657885805342	webdriver::server	DEBUG	<- 200 OK {"value":["a69b83d4-54fa-4d84-9fbc-a0c42064fa0e"]}
[task 2022-07-15T11:50:05.354Z] 11:50:05     INFO - PID 7844 | 1657885805342	webdriver::server	DEBUG	-> POST /session/ae2c9f13-933f-4519-9ddf-c6f94463f4f2/window {"handle": "a69b83d4-54fa-4d84-9fbc-a0c42064fa0e"}
[task 2022-07-15T11:50:05.355Z] 11:50:05     INFO - PID 7844 | 1657885805343	Marionette	DEBUG	0 -> [0,155,"WebDriver:SwitchToWindow",{"handle":"a69b83d4-54fa-4d84-9fbc-a0c42064fa0e"}]
[task 2022-07-15T11:50:05.356Z] 11:50:05     INFO - PID 7844 | 1657885805343	Marionette	DEBUG	0 <- [1,155,null,{"value":null}]
[task 2022-07-15T11:50:05.356Z] 11:50:05     INFO - PID 7844 | 1657885805344	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-07-15T11:50:05.357Z] 11:50:05     INFO - PID 7844 | 1657885805344	webdriver::server	DEBUG	-> POST /session/ae2c9f13-933f-4519-9ddf-c6f94463f4f2/window/rect {"width": 800, "height": 600}
[task 2022-07-15T11:50:05.358Z] 11:50:05     INFO - PID 7844 | 1657885805345	Marionette	DEBUG	0 -> [0,156,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2022-07-15T11:50:05.358Z] 11:50:05     INFO - PID 7844 | 1657885805345	Marionette	TRACE	Requested window geometry matches
[task 2022-07-15T11:50:05.359Z] 11:50:05     INFO - PID 7844 | 1657885805345	Marionette	DEBUG	0 <- [1,156,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-07-15T11:50:05.360Z] 11:50:05     INFO - PID 7844 | 1657885805346	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-07-15T11:50:05.360Z] 11:50:05     INFO - PID 7844 | 1657885805346	webdriver::server	DEBUG	-> POST /session/ae2c9f13-933f-4519-9ddf-c6f94463f4f2/frame {"id": null}
[task 2022-07-15T11:50:05.361Z] 11:50:05     INFO - PID 7844 | 1657885805347	Marionette	DEBUG	0 -> [0,157,"WebDriver:SwitchToFrame",{"id":null}]
[task 2022-07-15T11:50:05.362Z] 11:50:05     INFO - PID 7844 | 1657885805348	Marionette	DEBUG	0 <- [1,157,null,{"value":null}]
[task 2022-07-15T11:50:05.363Z] 11:50:05     INFO - PID 7844 | 1657885805348	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-07-15T11:50:05.364Z] 11:50:05     INFO - PID 7844 | 1657885805351	webdriver::server	DEBUG	-> DELETE /session/ae2c9f13-933f-4519-9ddf-c6f94463f4f2
[task 2022-07-15T11:50:05.364Z] 11:50:05     INFO - PID 7844 | 1657885805352	Marionette	DEBUG	0 -> [0,158,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2022-07-15T11:50:05.365Z] 11:50:05     INFO - PID 7844 | 1657885805352	Marionette	INFO	Stopped listening on port 62361
[task 2022-07-15T11:50:05.418Z] 11:50:05     INFO - PID 7844 | 1657885805425	Marionette	TRACE	Received observer notification quit-application
[task 2022-07-15T11:50:05.432Z] 11:50:05     INFO - PID 7844 | 1657885805431	Marionette	TRACE	Received observer notification quit-application
[task 2022-07-15T11:50:05.433Z] 11:50:05     INFO - PID 7844 | 1657885805432	Marionette	DEBUG	Marionette stopped listening
[task 2022-07-15T11:50:05.433Z] 11:50:05     INFO - PID 7844 | 1657885805433	Marionette	DEBUG	0 <- [1,158,null,{"cause":"shutdown","forced":false}]
[task 2022-07-15T11:50:05.463Z] 11:50:05     INFO - PID 7844 | 1657885805465	webdriver::server	DEBUG	Teardown session
[task 2022-07-15T11:50:05.470Z] 11:50:05     INFO - PID 7844 | 1657885805470	Marionette	DEBUG	Closed connection 0
[task 2022-07-15T11:50:05.499Z] 11:50:05     INFO - PID 7844 | [Parent 8636, Main Thread] WARNING: ContentParent: id=1a23fa9cc00 - BlockShutdown: CanSend.: file Z:/task_165787977686434/build/src/dom/ipc/ContentParent.cpp:3587
[task 2022-07-15T11:50:05.509Z] 11:50:05     INFO - PID 7844 | [Parent 8636, Main Thread] WARNING: ContentParent: id=1a23fa9cc00 - ShutDownProcess: Sent shutdown message.: file Z:/task_165787977686434/build/src/dom/ipc/ContentParent.cpp:1791
[task 2022-07-15T11:50:05.510Z] 11:50:05     INFO - PID 7844 | [Parent 8636, Main Thread] WARNING: ContentParent: id=1a24899a100 - BlockShutdown: CanSend.: file Z:/task_165787977686434/build/src/dom/ipc/ContentParent.cpp:3587
[task 2022-07-15T11:50:05.511Z] 11:50:05     INFO - PID 7844 | [Parent 8636, Main Thread] WARNING: ContentParent: id=1a24899a100 - ShutDownProcess: Sent shutdown message.: file Z:/task_165787977686434/build/src/dom/ipc/ContentParent.cpp:1791
[task 2022-07-15T11:50:05.512Z] 11:50:05     INFO - PID 7844 | [Parent 8636, Main Thread] WARNING: ContentParent: id=1a248997900 - BlockShutdown: CanSend.: file Z:/task_165787977686434/build/src/dom/ipc/ContentParent.cpp:3587
[task 2022-07-15T11:50:05.513Z] 11:50:05     INFO - PID 7844 | [Parent 8636, Main Thread] WARNING: ContentParent: id=1a248997900 - ShutDownProcess: Sent shutdown message.: file Z:/task_165787977686434/build/src/dom/ipc/ContentParent.cpp:1791
[task 2022-07-15T11:50:05.514Z] 11:50:05     INFO - PID 7844 | [Parent 8636, Main Thread] WARNING: ContentParent: id=1a248999200 - BlockShutdown: CanSend.: file Z:/task_165787977686434/build/src/dom/ipc/ContentParent.cpp:3587
[task 2022-07-15T11:50:05.515Z] 11:50:05     INFO - PID 7844 | [Parent 8636, Main Thread] WARNING: ContentParent: id=1a248999200 - ShutDownProcess: Sent shutdown message.: file Z:/task_165787977686434/build/src/dom/ipc/ContentParent.cpp:1791
[task 2022-07-15T11:50:05.544Z] 11:50:05     INFO - PID 7844 | [Parent 8636, Main Thread] WARNING: ContentParent: id=1a23fa9cc00 - ShutDownProcess: Closing channel.: file Z:/task_165787977686434/build/src/dom/ipc/ContentParent.cpp:1826
[task 2022-07-15T11:50:05.544Z] 11:50:05     INFO - PID 7844 | [Parent 8636, Main Thread] WARNING: ContentParent: id=1a23fa9cc00 - RemoveShutdownBlockers: file Z:/task_165787977686434/build/src/dom/ipc/ContentParent.cpp:3689
[task 2022-07-15T11:50:05.544Z] 11:50:05     INFO - PID 7844 | [Parent 8636, Main Thread] WARNING: ContentParent: id=1a248999200 - ShutDownProcess: Closing channel.: file Z:/task_165787977686434/build/src/dom/ipc/ContentParent.cpp:1826
[task 2022-07-15T11:50:05.544Z] 11:50:05     INFO - PID 7844 | [Parent 8636, Main Thread] WARNING: ContentParent: id=1a248999200 - RemoveShutdownBlockers: file Z:/task_165787977686434/build/src/dom/ipc/ContentParent.cpp:3689
[task 2022-07-15T11:50:05.544Z] 11:50:05     INFO - PID 7844 | [Parent 8636, Main Thread] WARNING: ContentParent: id=1a24899a100 - ShutDownProcess: Closing channel.: file Z:/task_165787977686434/build/src/dom/ipc/ContentParent.cpp:1826
[task 2022-07-15T11:50:05.544Z] 11:50:05     INFO - PID 7844 | [Parent 8636, Main Thread] WARNING: ContentParent: id=1a24899a100 - RemoveShutdownBlockers: file Z:/task_165787977686434/build/src/dom/ipc/ContentParent.cpp:3689
[task 2022-07-15T11:50:05.544Z] 11:50:05     INFO - PID 7844 | [Parent 8636, Main Thread] WARNING: ContentParent: id=1a248997900 - ShutDownProcess: Closing channel.: file Z:/task_165787977686434/build/src/dom/ipc/ContentParent.cpp:1826
[task 2022-07-15T11:50:05.544Z] 11:50:05     INFO - PID 7844 | [Parent 8636, Main Thread] WARNING: ContentParent: id=1a248997900 - RemoveShutdownBlockers: file Z:/task_165787977686434/build/src/dom/ipc/ContentParent.cpp:3689
[task 2022-07-15T11:50:05.843Z] 11:50:05     INFO - PID 7844 | JavaScript error: resource://gre/modules/TerminatorTelemetry.jsm, line 60: AbortError: IOUtils: Shutting down and refusing additional I/O tasks
[task 2022-07-15T11:50:07.430Z] 11:50:07     INFO - PID 7844 | Waiting in WillDestroyCurrentMessageLoop for pid 5848
[task 2022-07-15T11:50:57.275Z] 11:50:57     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/get_element_shadow_root/get.py | expected OK
[task 2022-07-15T11:50:57.278Z] 11:50:57     INFO - TEST-INFO took 55010ms
[task 2022-07-15T11:50:57.338Z] 11:50:57     INFO - Closing logging queue
[task 2022-07-15T11:50:57.346Z] 11:50:57     INFO - queue closed
[task 2022-07-15T11:50:57.859Z] 11:50:57     INFO - PID 6396 | 1657885857358	geckodriver	INFO	Listening on 127.0.0.1:49876
[task 2022-07-15T11:50:57.861Z] 11:50:57     INFO - Starting runner
[task 2022-07-15T11:50:58.657Z] 11:50:58     INFO - TEST-START | /webdriver/tests/get_element_shadow_root/user_prompts.py

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

There is a hang during shutdown of Firefox:
https://treeherder.mozilla.org/logviewer?job_id=384469789&repo=mozilla-central&lineNumber=73844-73846

[task 2022-07-15T11:50:05.843Z] 11:50:05     INFO - PID 7844 | JavaScript error: resource://gre/modules/TerminatorTelemetry.jsm, line 60: AbortError: IOUtils: Shutting down and refusing additional I/O tasks
[task 2022-07-15T11:50:07.430Z] 11:50:07     INFO - PID 7844 | Waiting in WillDestroyCurrentMessageLoop for pid 5848
[task 2022-07-15T11:50:57.275Z] 11:50:57     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/get_element_shadow_root/get.py | expected OK

Chris could this be Telemetry related or a side-effect from a CCOV build?

Comment 2

[Chris H-C :chutten]

We have this existing in non-CCOV builds (bug 1779493) and may be a side-effect of how Telemetry needs to write to disk later than IOUtils (currently) would like us to (bug 1769152).

We may need to revert bug 1749620 to return TerminatorTelemetry back to OS.file usage to stop these aborterrors from happening.

ni?barret for IOUtils migration planning: How's bug 1769152 looking wrt timeline? Is it possible or worthwhile to go back to using osfile for TerminatorTelemetry given the intermittents we might be seeing as a result?

Comment 3

[Intermittent Failures Robot]

1 failures in 3341 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows10-64-2004-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1779759&startday=2022-07-11&endday=2022-07-17&tree=all

Comment 4

[Beth Rennie [:beth] (she/her)]

I have a patch that half works locally. I can prioritize working on it at the beginning of the Fx105 cycle, so maybe a backout for now would be goodl

Comment 5

[Chris H-C :chutten]

I'm working on something else at the moment, but I might be able to get to this revert soonish.

Comment 6

[Chris H-C :chutten]

Attachment: Bug 1779759 - Put TerminatorTelemetry back on osfile.jsm for late writes r?barret!

This reverts commit 3e67ed2191aeb4844f64a83e94160b5860e7ebf4.

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/313771167333
Put TerminatorTelemetry back on osfile.jsm for late writes r=barret

Comment 8

[Sandor Molnar[:smolnar]]

Backed out changeset 313771167333 (bug 1779759) for causing browser-chrome failures in browser/base/content/test/performance/browser_startup.js

Backout link: https://hg.mozilla.org/integration/autoland/rev/c7cd33940024f3502af1e33ed365262a2fc678eb

Push with failures

Failure log

TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup.js | resource://gre/modules/osfile.jsm is not allowed before becoming idle -

Comment 9

[Chris H-C :chutten]

Dagnabbit. Okay Barret, looks like the simple backout isn't gonna work out so well. I leave the fix in your hands.

Comment 10

[BugBot [:suhaib / :marco/ :calixte]]

:mathew.hodson, since you are the author of the regressor, bug 1749620, could you take a look?
For more information, please visit auto_nag documentation.

Comment 11

[Mathew Hodson]

Looks like :barret will fix this in bug 1769152.

Comment 12

[Beth Rennie [:beth] (she/her)]

Attachment: Bug 1779759 - Block shutdown for terminator telemetry r?chutten

Depends on D152923

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/44b5ce9432c9
Block shutdown for terminator telemetry r=chutten

Comment 14

[Cristian Tuns]

Backed out for causing build bustages on IOUtils.cpp

• Backout link
• Push with failures
• Failure Log
• Failure line: package> Assertion failure: aPhase >= IOUtils::ShutdownPhase::ProfileBeforeChange && aPhase < IOUtils::ShutdownPhase::XpcomWillShutdown, at /builds/worker/checkouts/gecko/dom/system/IOUtils.cpp:2016

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/84d85b2c2c57
Block shutdown for terminator telemetry r=chutten

Comment 16

[Sandor Molnar[:smolnar]]

Backed out for causing build bustages on IOUtils.cpp

Backout link: https://hg.mozilla.org/integration/autoland/rev/b6d7397f08835225f847ac613f38c95322e7214e

Push with failures

Failure log build bustage

Failure log crashtest

WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"IOUtils Blocker (xpcom-will-shutdown)","state":"(none)","filename":"/builds/worker/checkouts/gecko/dom/system/IOUtils.cpp","lineNumber":2194,"stack":"IOUtils::EventQueue::SetShutdownHooks"}] Barrier: xpcom-will-shutdown
[task 2022-08-09T18:07:51.247Z] 18:07:51     INFO -  package> FATAL ERROR: AsyncShutdown timeout in xpcom-will-shutdown Conditions: [{"name":"IOUtils Blocker (xpcom-will-shutdown)","state":"(none)","filename":"/builds/worker/checkouts/gecko/dom/system/IOUtils.cpp","lineNumber":2194,"stack":"IOUtils::EventQueue::SetShutdownHooks"}] At least one completion condition failed to complete within a reasonable amount of time. Causing a crash to ensure that we do not leave the user with an unresponsive process draining resources.
[task 2022-08-09T18:07:51.247Z] 18:07:51     INFO -  package> WARNING: No crash reporter available
[task 2022-08-09T18:07:51.247Z] 18:07:51     INFO -  package> [Parent 29518, Main Thread] ###!!! ABORT: file /builds/worker/checkouts/gecko/dom/system/IOUtils.cpp:2194

Comment 17

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Updating the bug's summary for a better test failure classification experience given that this could happen basically for each and every of our wdspec tests.

Comment 18

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1749620

Comment 19

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

This specific shutdown hang causes quite some test failures for wdspec tests for Windows ccov builds (bug 1783217).

Barret do you think that we can get this fixed sometime soon?

Comment 20

[Beth Rennie [:beth] (she/her)]

Just triggered re-landing.

Comment 21

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/adc608dc4add
Block shutdown for terminator telemetry r=chutten

Comment 22

[Narcis Beleuzu [:NarcisB]]

Backed out for mochitest failures on TerminatorTelemetry.jsm

Backout link: https://hg.mozilla.org/integration/autoland/rev/65f93af1063b755665d8e7991755f64122c8cd2a
Log link: https://treeherder.mozilla.org/logviewer?job_id=387199591&repo=autoland&lineNumber=2836

Comment 23

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/18b95d8fd376
Block shutdown for terminator telemetry r=chutten

Comment 24

[Beth Rennie [:beth] (she/her)]

I think this updated patch should fix the remaining failures.

Comment 25

[Cosmin Sabou [:CosminS]]

Backed out for causing TerminatoryTelemetry related test failures.

Push with failures: https://treeherder.mozilla.org/jobs?repo=autoland&selectedTaskRun=ehroMv0QSdOZpvlOj-JnsQ.0&resultStatus=testfailed%2Cbusted%2Cexception&revision=18b95d8fd376ecafa1d63983e1fdf790959a872f

Failure log: https://treeherder.mozilla.org/logviewer?job_id=387907080&repo=autoland
https://treeherder.mozilla.org/logviewer?job_id=387907079&repo=autoland

Backout link: https://hg.mozilla.org/integration/autoland/rev/f5e9cd2493e952cc36cbe9ad447f114db77a9eca

Comment 26

[Beth Rennie [:beth] (she/her)]

This patch would have worked if nsTerminatorTelemetry used modern JS, but because it uses old ES5 style callbacks, it breaks here:

nsTerminatorTelemetry.prototype = {
  // ...
  observe: function(/* ... */) {
    // ...
   (async function() {
      // ...
      this._deferred.resolve(); // this is not defined because none of this functions bind `this`.
    })();
  },
}

Comment 27

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/3bb45c9d60de
Block shutdown for terminator telemetry r=chutten

Comment 28

[Cristian Tuns]

https://hg.mozilla.org/mozilla-central/rev/3bb45c9d60de

Comment 29

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Barret do you think that this patch should be uplifted to 104. Or is it ok to keep it on central only given that it only seems to affect CCOV builds? But there might maybe other factors as well to trigger that behavior and seeing release users being affected sounds unfortunate.

Comment 30

[Beth Rennie [:beth] (she/her)]

This really shouldn't be affecting actual users. The issue only manifests when shutdown occurs part-way through browser startup, before we reach a stable state, which really only happens in tests.