1754326 - Intermittent FATAL ERROR: AsyncShutdown timeout in IOUtils: waiting for profileBeforeChange IO to complete Conditions: [{"name":"SessionFile: Finish writing Session Restore data","state":{"options":{"isFinalWrite":false,"performShutdownCleanup":false},"at

Status: RESOLVED DUPLICATE of bug 1743674

(Firefox :: Session Restore, defect)

Description

[Treeherder Bug Filer]

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

---

[task 2022-02-08T21:16:04.579Z] 21:16:04     INFO - TEST-OK | browser/base/content/test/sanitize/browser_sanitizeDialog.js | took 7053ms
[task 2022-02-08T21:16:04.592Z] 21:16:04     INFO - checking window state
[task 2022-02-08T21:16:05.567Z] 21:16:05     INFO - GECKO(2424) | ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-08T21:16:05.577Z] 21:16:05     INFO - GECKO(2424) | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-08T21:16:05.577Z] 21:16:05     INFO - GECKO(2424) | ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-08T21:16:06.047Z] 21:16:06     INFO - GECKO(2424) | [Parent 6228, IPC I/O Parent] WARNING: file /builds/worker/checkouts/gecko/ipc/chromium/src/base/process_util_win.cc:167
[task 2022-02-08T21:16:06.056Z] 21:16:06     INFO - GECKO(2424) | [Parent 6228, IPC I/O Parent] WARNING: file /builds/worker/checkouts/gecko/ipc/chromium/src/base/process_util_win.cc:167
[task 2022-02-08T21:16:06.060Z] 21:16:06     INFO - GECKO(2424) | [Parent 6228, IPC I/O Parent] WARNING: file /builds/worker/checkouts/gecko/ipc/chromium/src/base/process_util_win.cc:167
[task 2022-02-08T21:16:06.602Z] 21:16:06     INFO - GECKO(2424) | Completed ShutdownLeaks collections in process 6720
[task 2022-02-08T21:16:06.635Z] 21:16:06     INFO - GECKO(2424) | Completed ShutdownLeaks collections in process 7164
[task 2022-02-08T21:16:06.656Z] 21:16:06     INFO - GECKO(2424) | Completed ShutdownLeaks collections in process 7592
[task 2022-02-08T21:16:06.734Z] 21:16:06     INFO - GECKO(2424) | Completed ShutdownLeaks collections in process 3412
[task 2022-02-08T21:16:07.251Z] 21:16:07     INFO - GECKO(2424) | Completed ShutdownLeaks collections in process 6228
[task 2022-02-08T21:16:07.266Z] 21:16:07     INFO - TEST-START | Shutdown
[task 2022-02-08T21:16:07.266Z] 21:16:07     INFO - Browser Chrome Test Summary
[task 2022-02-08T21:16:07.267Z] 21:16:07     INFO - Passed:  619
[task 2022-02-08T21:16:07.267Z] 21:16:07     INFO - Failed:  0
[task 2022-02-08T21:16:07.268Z] 21:16:07     INFO - Todo:    0
[task 2022-02-08T21:16:07.268Z] 21:16:07     INFO - Mode:    e10s
[task 2022-02-08T21:16:07.269Z] 21:16:07     INFO - *** End BrowserChrome Test Results ***
[task 2022-02-08T21:16:07.420Z] 21:16:07     INFO - GECKO(2424) | 1644354967423	Marionette	TRACE	Received observer notification quit-application
[task 2022-02-08T21:16:07.425Z] 21:16:07     INFO - GECKO(2424) | 1644354967424	Marionette	INFO	Stopped listening on port 2828
[task 2022-02-08T21:16:07.426Z] 21:16:07     INFO - GECKO(2424) | 1644354967425	Marionette	DEBUG	Marionette stopped listening
[task 2022-02-08T21:16:07.536Z] 21:16:07     INFO - GECKO(2424) | JavaScript error: resource://gre/modules/URLQueryStrippingListService.jsm, line 90: TypeError: can't access property "removeEventListener", Services.cpmm.sharedData is null
[task 2022-02-08T21:16:07.620Z] 21:16:07     INFO - GECKO(2424) | JavaScript error: resource://gre/modules/URLQueryStrippingListService.jsm, line 90: TypeError: can't access property "removeEventListener", Services.cpmm.sharedData is null
[task 2022-02-08T21:16:07.626Z] 21:16:07     INFO - GECKO(2424) | ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-08T21:16:07.627Z] 21:16:07     INFO - GECKO(2424) | JavaScript error: resource://gre/modules/URLQueryStrippingListService.jsm, line 90: TypeError: can't access property "removeEventListener", Services.cpmm.sharedData is null
[task 2022-02-08T21:16:07.632Z] 21:16:07     INFO - GECKO(2424) | JavaScript error: resource://gre/modules/URLQueryStrippingListService.jsm, line 90: TypeError: can't access property "removeEventListener", Services.cpmm.sharedData is null
[task 2022-02-08T21:16:17.599Z] 21:16:17     INFO - GECKO(2424) | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"SessionFile: Finish writing Session Restore data","state":{"options":{"isFinalWrite":false,"performShutdownCleanup":false},"attempts":69,"successes":68,"failures":0},"filename":"resource:///modules/sessionstore/SessionFile.jsm","lineNumber":488,"stack":["resource:///modules/sessionstore/SessionFile.jsm:write:488","resource:///modules/sessionstore/SessionFile.jsm:write:63","resource:///modules/sessionstore/SessionSaver.jsm:_writeState:367","resource:///modules/sessionstore/SessionSaver.jsm:_saveState:301","resource:///modules/sessionstore/SessionSaver.jsm:run:161","resource:///modules/sessionstore/SessionSaver.jsm:run:76","resource:///modules/sessionstore/SessionStore.jsm:ssi_onPurgeSessionHistory/<:2316"]}] Barrier: IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-02-08T21:16:17.619Z] 21:16:17     INFO - GECKO(2424) | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"IOUtils Blocker (profile-before-change)","state":"(none)","filename":"/builds/worker/checkouts/gecko/dom/system/IOUtils.cpp","lineNumber":1901,"stack":"IOUtils::EventQueue::SetShutdownHooks"}] Barrier: profile-before-change
[task 2022-02-08T21:16:22.547Z] 21:16:22     INFO - GECKO(2424) | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 443))
[task 2022-02-08T21:21:08.601Z] 21:21:08     INFO - GECKO(2424) | FATAL ERROR: AsyncShutdown timeout in IOUtils: waiting for profileBeforeChange IO to complete Conditions: [{"name":"SessionFile: Finish writing Session Restore data","state":{"options":{"isFinalWrite":false,"performShutdownCleanup":false},"attempts":69,"successes":68,"failures":0},"filename":"resource:///modules/sessionstore/SessionFile.jsm","lineNumber":488,"stack":["resource:///modules/sessionstore/SessionFile.jsm:write:488","resource:///modules/sessionstore/SessionFile.jsm:write:63","resource:///modules/sessionstore/SessionSaver.jsm:_writeState:367","resource:///modules/sessionstore/SessionSaver.jsm:_saveState:301","resource:///modules/sessionstore/SessionSaver.jsm:run:161","resource:///modules/sessionstore/SessionSaver.jsm:run:76","resource:///modules/sessionstore/SessionStore.jsm:ssi_onPurgeSessionHistory/<:2316"]}] 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-02-08T21:21:08.606Z] 21:21:08     INFO - GECKO(2424) | WARNING: No crash reporter available
[task 2022-02-08T21:21:08.606Z] 21:21:08     INFO - GECKO(2424) | [Parent 6228, Main Thread] ###!!! ABORT: file resource:///modules/sessionstore/SessionFile.jsm:488
[task 2022-02-08T21:21:10.430Z] 21:21:10     INFO - TEST-INFO | Main app process: exit 80000003
[task 2022-02-08T21:21:10.437Z] 21:21:10     INFO - Buffered messages finished
[task 2022-02-08T21:21:10.437Z] 21:21:10    ERROR - TEST-UNEXPECTED-FAIL | Last test finished | application terminated with exit code 2147483651
[task 2022-02-08T21:21:10.438Z] 21:21:10     INFO - runtests.py | Application ran for: 0:06:27.880867

Comment 2

[:Gijs (he/him)]

I'm confused about the severity here; the graph for orangefactor currently says:

25 failures on trunk in the past week (link)

but https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2022-02-04&endday=2022-02-11&tree=trunk&bug=1754326 only shows 8 oranges. But AFAICT there weren't significant changes to IOUtils immediately before the oranges started (the change from e.g. bug 1749996 is older). There was a change in session restore on Feb 7 (bug 1728800) but even then I would have expected this to start failing sooner if that was the cause. So I'm not sure what happened here.

From the failing log:

{"name":"SessionFile: Finish writing Session Restore data","state":{"options":{"isFinalWrite":false,"performShutdownCleanup":false},"attempts":69,"successes":68,"failures":0}

The isFinalWrite being false is fishy here, but off-hand I would have no idea what'd cause that.

Naively, I'm hoping a fix in bug 1752853 will help, as it cuts out the worker intermediary for writing to the file -- but who knows.

Comment 3

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

(In reply to :Gijs (he/him) from comment #2)

I'm confused about the severity here; the graph for orangefactor currently says:

25 failures on trunk in the past week (link)

but https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2022-02-04&endday=2022-02-11&tree=trunk&bug=1754326 only shows 8 oranges.

The default view only shows trunk, the other failures are on beta and try.

Comment 4

[:Gijs (he/him)]

(In reply to Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout) from comment #3)

(In reply to :Gijs (he/him) from comment #2)

I'm confused about the severity here; the graph for orangefactor currently says:

25 failures on trunk in the past week (link)

but https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2022-02-04&endday=2022-02-11&tree=trunk&bug=1754326 only shows 8 oranges.

The default view only shows trunk, the other failures are on beta and try.

Thanks. So either the thing causing this is something that got landed before merge (but then why were there no failures on Feb 7?) or it got uplifted. I'm also wondering if this is just a pre-existing intermittent and bug 1749996 changed the message, or something, as it will have caused the asyncshutdown state description to change.

Is there any way to find out which? Did we have issues running the failing tests around the weekend / on merge day, or something, that would explain why this didn't fail sooner?

Comment 5

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

First failure is https://treeherder.mozilla.org/jobs?repo=try&revision=6baf509f1d46b46f975dad3a2ea9ebd5104595d4&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=retry&filter-resultStatus=usercancel&filter-resultStatus=runnable&selectedTaskRun=VuN4asVlTx6GBqE9JkBwvA.0 one. There is frequent shutdown failure for Windows asan browser-chrome tasks on previous pushes.

Comment 6

[Barret Rennie [:barret] (they/them)]

Bug 1749996 did change the message -- It never used to say IOUtils and instead said AsyncShutdown.

That first failure linked was me adding logging to figure out what was happening.

Comment 7

[Intermittent Failures Robot]

30 failures in 3711 pushes (0.008 failures/push) 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:

• try: 11
• mozilla-beta: 8
• autoland: 6
• mozilla-central: 5

Platform and build breakdown:

• windows7-32-shippable-qr: 3
  • opt: 3
• windows10-64-2004-asan-qr: 11
  • opt: 11
• linux1804-64-qr: 3
  • debug: 3
• linux1804-64-devedition-qr: 3
  • opt: 3
• linux1804-64-shippable-qr: 5
  • opt: 5
• windows10-64-2004-devedition-qr: 3
  • opt: 3
• windows10-64-2004-ccov-qr: 1
  • opt: 1
• windows10-64-2004-qr: 1
  • debug: 1

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

Comment 8

[Ryan VanderMeulen [:RyanVM]]

If this is a signature change, can we dupe this bug to the one for the previous signature?

Comment 9

[Intermittent Failures Robot]

56 failures in 3281 pushes (0.017 failures/push) were associated with this bug in the last 7 days.

This is the #12 most frequent failure this week.

** 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: 12
• mozilla-beta: 26
• try: 9
• mozilla-central: 7
• mozilla-release: 2

Platform and build breakdown:

• windows10-32-2004-qr: 4
  • debug: 4
• windows10-64-2004-asan-qr: 14
  • opt: 14
• windows10-64-2004-shippable-qr: 8
  • opt: 8
• windows7-32-shippable-qr: 7
  • opt: 7
• linux1804-64-qr: 3
  • debug: 3
• linux1804-64-asan-qr: 1
  • opt: 1
• linux1804-64-shippable-qr: 10
  • opt: 10
• windows10-64-2004-devedition-qr: 2
  • opt: 2
• windows10-64-2004-qr: 4
  • debug: 4
• linux1804-64-devedition-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1754326&startday=2022-02-14&endday=2022-02-20&tree=all

Comment 10

[:Gijs (he/him)]

(In reply to Ryan VanderMeulen [:RyanVM] from comment #8)

If this is a signature change, can we dupe this bug to the one for the previous signature?

Looks like bug https://bugzilla.mozilla.org/show_bug.cgi?id=1743674 is the one?