Closed Bug 1652192 Opened 5 years ago Closed 3 years ago

Intermittent Windows accessible/tests/browser/states/browser_test_visibility.js | Test timed out -

Categories

(Core :: Disability Access APIs, defect, P5)

defect

Tracking

()

RESOLVED WORKSFORME

People

(Reporter: intermittent-bug-filer, Assigned: Jamie)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell disabled])

Attachments

(2 files)

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


[task 2020-07-10T23:37:43.279Z] 23:37:43     INFO - TEST-START | accessible/tests/browser/states/browser_test_visibility.js
[task 2020-07-10T23:38:28.304Z] 23:38:28     INFO - TEST-INFO | started process screenshot
[task 2020-07-10T23:38:28.354Z] 23:38:28     INFO - TEST-INFO | screenshot: exit 0
[task 2020-07-10T23:38:28.354Z] 23:38:28     INFO - Buffered messages logged at 23:37:43
[task 2020-07-10T23:38:28.354Z] 23:38:28     INFO - Entering test bound 
[task 2020-07-10T23:38:28.354Z] 23:38:28     INFO - Buffered messages logged at 23:37:47
[task 2020-07-10T23:38:28.354Z] 23:38:28     INFO - TEST-PASS | accessible/tests/browser/states/browser_test_visibility.js | e10s enabled - 
[task 2020-07-10T23:38:28.355Z] 23:38:28     INFO - TEST-PASS | accessible/tests/browser/states/browser_test_visibility.js | Actually remote browser - 
[task 2020-07-10T23:38:28.355Z] 23:38:28     INFO - Buffered messages finished
[task 2020-07-10T23:38:28.355Z] 23:38:28     INFO - TEST-UNEXPECTED-FAIL | accessible/tests/browser/states/browser_test_visibility.js | Test timed out - 
[task 2020-07-10T23:38:28.355Z] 23:38:28     INFO - GECKO(2564) | MEMORY STAT | vsize 2104154MB | vsizeMaxContiguous 69708962MB | residentFast 238MB | heapAllocated 76MB
[task 2020-07-10T23:38:28.355Z] 23:38:28     INFO - TEST-OK | accessible/tests/browser/states/browser_test_visibility.js | took 45073ms
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 5 years ago5 years ago
Resolution: --- → INCOMPLETE

In the last 7 days there have been 21 occurrences, mostly on windows10-64-qr opt.

Recent failure: https://treeherder.mozilla.org/logviewer?job_id=322595543&repo=autoland&lineNumber=2049

James, does this require developer attention?

Flags: needinfo?(jteh)
Whiteboard: [stockwell needswork:owner]

In the last 7 days there have been 20 occurrences, all on windows10-64-qr debug and opt.

Recent failure: https://treeherder.mozilla.org/logviewer?job_id=325026654&repo=autoland&lineNumber=2073

I'm not going to have time to look at this before I go on leave. If it needs to be disabled, that's fine; I'll try to deal with it (or assign it) in the new year.

(In reply to James Teh [:Jamie] (away returning 11 January) from comment #22)

I'm not going to have time to look at this before I go on leave. If it needs to be disabled, that's fine; I'll try to deal with it (or assign it) in the new year.

We'll continue monitoring and if it reaches the disable recommended queue, we'll make a patch. Thank you.

Recent failures are missclassifications on try.

Whiteboard: [stockwell unknown] → [stockwell unknown][stockwell needswork:owner]
Flags: needinfo?(jteh)
Flags: needinfo?(jteh)

I can't reproduce this on try, so I'm landing this so I can get (hopefully) useful info next time it fails.

Assignee: nobody → jteh
Assignee: jteh → nobody
Flags: needinfo?(jteh)
Keywords: leave-open
Assignee: nobody → jteh
Pushed by jteh@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/4998c3672d36 Enable event logging for accessible/tests/browser/states/browser_test_visibility.js. r=yzen

I don't think this is specific to this test, but rather, I think it's an instance of a wider (but rare) problem. We're seeing a similar failure in bug 1492259 and probably others. Frustratingly, I can't reproduce it locally, nor on try. I've spent days trying to trace through and document the DocAccessible creation/loading code to figure out what could be going wrong, but I'm still at a loss.

I initially thought this might be a problem with our firing of document load complete events. However, looking at the events logged in the intermittents after the patch I landed here, it looks like we never get any events for the actual test document. I would have expected focus at least. That means either:

  1. We don't create the DocAccessible in the content process;
  2. We don't send it to the parent process; or
  3. We don't send events to the parent process.

The fact that this only seems to happen on Windows makes me think we're not getting events, since only Windows defers all events until after the parent COM proxy is received. Assuming that's correct, that of course raises the question: why is the parent COM proxy not being received? Also, if that were true, we should hit MOZ_ASSERT(!aParentCOMProxy.IsNull());, which isn't showing up in the debug failures.

Depends on: 1708336

Eek! It looks like the content process is crashing in that log. I don't understand why a timeout gets flagged instead of just a crash. I've filed bug 1709250 to deal with this and will have a patch up shortly.

Flags: needinfo?(jteh)
Whiteboard: [stockwell unknown][stockwell needswork:owner] → [stockwell needswork:owner]

There are 33 total failures in the last 7 days on

  • windows10-32-qr debug
  • windows10-64-asan-qr opt
  • windows10-64-qr debug
  • windows10-64-shippable-qr opt

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=345117124&repo=autoland&lineNumber=2931

[task 2021-07-13T20:57:33.489Z] 20:57:33 INFO - TEST-START | accessible/tests/browser/states/browser_test_visibility.js
[task 2021-07-13T20:57:33.515Z] 20:57:33 INFO - GECKO(1084) | [Child 4384: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 29c3a6bc400 == 2 [pid = 4384] [id = 1]
[task 2021-07-13T20:57:33.516Z] 20:57:33 INFO - GECKO(1084) | [Child 4384: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 4 (29c415d6e40) [pid = 4384] [serial = 4] [outer = 0]
[task 2021-07-13T20:57:33.516Z] 20:57:33 INFO - GECKO(1084) | [Child 4384: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 5 (29c41d3e400) [pid = 4384] [serial = 5] [outer = 29c415d6e40]
[task 2021-07-13T20:57:33.562Z] 20:57:33 INFO - GECKO(1084) | [Child 4384: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 6 (29c43320000) [pid = 4384] [serial = 6] [outer = 29c415d6e40]
[task 2021-07-13T20:57:37.452Z] 20:57:37 INFO - GECKO(1084) | [Child 10100, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-07-13T20:57:37.459Z] 20:57:37 INFO - GECKO(1084) | must wait for focus in content
[task 2021-07-13T20:57:37.628Z] 20:57:37 INFO - GECKO(1084) | [Child 10100: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 1e7154a2400 == 2 [pid = 10100] [id = 0] [url = about:blank]
[task 2021-07-13T20:57:37.629Z] 20:57:37 INFO - GECKO(1084) | [Child 10100: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 1e715b49800 == 1 [pid = 10100] [id = 1] [url = http://www.example.com/]
[task 2021-07-13T20:57:37.667Z] 20:57:37 INFO - GECKO(1084) | [Child 10100: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 8 (1e715bf2200) [pid = 10100] [serial = 5] [outer = 0] [url = http://www.example.com/]
[task 2021-07-13T20:57:37.875Z] 20:57:37 INFO - GECKO(1084) | [Child 1984: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 1f2c888c000 == 1 [pid = 1984] [id = 0] [url = chrome://gfxsanity/content/sanitytest.html]
[task 2021-07-13T20:57:37.875Z] 20:57:37 INFO - GECKO(1084) | [Child 1984: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 1f2c9051c00 == 0 [pid = 1984] [id = 1] [url = about:blank]
[task 2021-07-13T20:57:37.898Z] 20:57:37 INFO - GECKO(1084) | [Child 1984: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (1f2c88d5900) [pid = 1984] [serial = 1] [outer = 0] [url = chrome://gfxsanity/content/sanitytest.html]
[task 2021-07-13T20:57:37.898Z] 20:57:37 INFO - GECKO(1084) | [Child 1984: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (1f2c90b2580) [pid = 1984] [serial = 4] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:38.218Z] 20:57:38 INFO - GECKO(1084) | [Parent 644: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 217fc111c00 == 6 [pid = 644] [id = 7] [url = about:blank]
[task 2021-07-13T20:57:38.540Z] 20:57:38 INFO - GECKO(1084) | [Parent 644: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 16 (217e4fd3ac0) [pid = 644] [serial = 1] [outer = 0] [url = chrome://gfxsanity/content/sanityparent.html]
[task 2021-07-13T20:57:38.586Z] 20:57:38 INFO - GECKO(1084) | [Child 9944: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 1af474c6400 == 4 [pid = 9944] [id = 2] [url = moz-extension://918fb04b-5028-4717-ae5e-feab53ebfa55/_generated_background_page.html]
[task 2021-07-13T20:57:38.586Z] 20:57:38 INFO - GECKO(1084) | [Child 9944: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 14 (1af4e89e3c0) [pid = 9944] [serial = 5] [outer = 0] [url = moz-extension://918fb04b-5028-4717-ae5e-feab53ebfa55/_generated_background_page.html]
[task 2021-07-13T20:57:39.935Z] 20:57:39 INFO - GECKO(1084) | [Child 4384: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 29c415a3800 == 1 [pid = 4384] [id = 0] [url = data:text/html;charset=utf-8,%3Chtml%3E%0A%20%20%20%20%20%20%3Chead%3E%0A%20%20%20%20%20%20%20%20%3Cmeta%20charset%3D%22utf-8%22%2F%3E%0A%20%20%20%20%20%20%20%20%3Ctitle%3EAccessibility%20Test%3C%2Ftitle%3E%0A%20%20%20%20%20%20%3C%2Fhead%3E%0A%20%20%20%20%20%20%3Cbody%20id%3D%22body%22%3E%0A%20%20%3Ca%20id%3D%22link_traversed%22%20href%3D%22http%3A%2F%2Fwww.example.com%22%20target%3D%22_top%22%3E%0A%20%20%20%20example.com%0A%20%20%3C%2Fa%3E%3C%2Fbody%3E%0A%20%20%20%20%3C%2Fhtml%3E]
[task 2021-07-13T20:57:39.960Z] 20:57:39 INFO - GECKO(1084) | [Child 4384: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 5 (29c415d6740) [pid = 4384] [serial = 1] [outer = 0] [url = data:text/html;charset=utf-8,%3Chtml%3E%0A%20%20%20%20%20%20%3Chead%3E%0A%20%20%20%20%20%20%20%20%3Cmeta%20charset%3D%22utf-8%22%2F%3E%0A%20%20%20%20%20%20%20%20%3Ctitle%3EAccessibility%20Test%3C%2Ftitle%3E%0A%20%20%20%20%20%20%3C%2Fhead%3E%0A%20%20%20%20%20%20%3Cbody%20id%3D%22body%22%3E%0A%20%20%3Ca%20id%3D%22link_traversed%22%20href%3D%22http%3A%2F%2Fwww.example.com%22%20target%3D%22_top%22%3E%0A%20%20%20%20example.com%0A%20%20%3C%2Fa%3E%3C%2Fbody%3E%0A%20%20%20%20%3C%2Fhtml%3E]
[task 2021-07-13T20:57:41.718Z] 20:57:41 INFO - GECKO(1084) | [Child 10100: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 7 (1e715b4e800) [pid = 10100] [serial = 6] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:41.719Z] 20:57:41 INFO - GECKO(1084) | [Child 10100: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 6 (1e7154a3400) [pid = 10100] [serial = 2] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:41.719Z] 20:57:41 INFO - GECKO(1084) | [Child 10100: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 5 (1e717645c00) [pid = 10100] [serial = 7] [outer = 0] [url = http://www.example.com/]
[task 2021-07-13T20:57:41.752Z] 20:57:41 INFO - GECKO(1084) | [Child 10100: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (1e7154d2900) [pid = 10100] [serial = 1] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:41.956Z] 20:57:41 INFO - GECKO(1084) | [Child 1984: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (1f2c9050800) [pid = 1984] [serial = 3] [outer = 0] [url = chrome://gfxsanity/content/sanitytest.html]
[task 2021-07-13T20:57:41.957Z] 20:57:41 INFO - GECKO(1084) | [Child 1984: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (1f2c888d000) [pid = 1984] [serial = 2] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:41.957Z] 20:57:41 INFO - GECKO(1084) | [Child 1984: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (1f2c9052c00) [pid = 1984] [serial = 5] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:42.531Z] 20:57:42 INFO - GECKO(1084) | [Parent 644: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 217fa84a400 == 5 [pid = 644] [id = 6] [url = chrome://browser/content/browser.xhtml]
[task 2021-07-13T20:57:42.531Z] 20:57:42 INFO - GECKO(1084) | [Parent 644: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 15 (217f1f9b000) [pid = 644] [serial = 2] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:42.532Z] 20:57:42 INFO - GECKO(1084) | [Parent 644: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 14 (217f9aed800) [pid = 644] [serial = 10] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:42.637Z] 20:57:42 INFO - GECKO(1084) | [Child 9944: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 13 (1af5041dc00) [pid = 9944] [serial = 13] [outer = 0] [url = moz-extension://918fb04b-5028-4717-ae5e-feab53ebfa55/_generated_background_page.html]
[task 2021-07-13T20:57:42.637Z] 20:57:42 INFO - GECKO(1084) | [Child 9944: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 12 (1af4e84f000) [pid = 9944] [serial = 10] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:42.638Z] 20:57:42 INFO - GECKO(1084) | [Child 9944: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (1af4e84d400) [pid = 9944] [serial = 8] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:42.638Z] 20:57:42 INFO - GECKO(1084) | [Child 9944: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (1af4e84b800) [pid = 9944] [serial = 6] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:42.639Z] 20:57:42 INFO - GECKO(1084) | [Child 9944: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 9 (1af4e846800) [pid = 9944] [serial = 2] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:42.639Z] 20:57:42 INFO - GECKO(1084) | [Child 9944: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 8 (1af4e84a800) [pid = 9944] [serial = 4] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:42.825Z] 20:57:42 INFO - GECKO(1084) | [Parent 644: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 13 (217fc697740) [pid = 644] [serial = 16] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:42.825Z] 20:57:42 INFO - GECKO(1084) | [Parent 644: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 12 (217fb8d0e40) [pid = 644] [serial = 14] [outer = 0] [url = chrome://browser/content/browser.xhtml]
[task 2021-07-13T20:57:43.107Z] 20:57:43 INFO - GECKO(1084) | [Child 8200: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (1c60ac33400) [pid = 8200] [serial = 2] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:44.021Z] 20:57:44 INFO - GECKO(1084) | [Child 4384: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (29c41d45400) [pid = 4384] [serial = 3] [outer = 0] [url = data:text/html;charset=utf-8,%3Chtml%3E%0A%20%20%20%20%20%20%3Chead%3E%0A%20%20%20%20%20%20%20%20%3Cmeta%20charset%3D%22utf-8%22%2F%3E%0A%20%20%20%20%20%20%20%20%3Ctitle%3EAccessibility%20Test%3C%2Ftitle%3E%0A%20%20%20%20%20%20%3C%2Fhead%3E%0A%20%20%20%20%20%20%3Cbody%20id%3D%22body%22%3E%0A%20%20%3Ca%20id%3D%22link_traversed%22%20href%3D%22http%3A%2F%2Fwww.example.com%22%20target%3D%22_top%22%3E%0A%20%20%20%20example.com%0A%20%20%3C%2Fa%3E%3C%2Fbody%3E%0A%20%20%20%20%3C%2Fhtml%3E]
[task 2021-07-13T20:57:44.021Z] 20:57:44 INFO - GECKO(1084) | [Child 4384: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (29c415a7800) [pid = 4384] [serial = 2] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:44.022Z] 20:57:44 INFO - GECKO(1084) | [Child 4384: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (29c41d3e400) [pid = 4384] [serial = 5] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:45.817Z] 20:57:45 INFO - GECKO(1084) | [Child 10100: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (1e715b49400) [pid = 10100] [serial = 3] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:45.817Z] 20:57:45 INFO - GECKO(1084) | [Child 10100: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (1e715b51400) [pid = 10100] [serial = 4] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:46.777Z] 20:57:46 INFO - GECKO(1084) | [Parent 644: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (217fc1dc400) [pid = 644] [serial = 17] [outer = 0] [url = about:blank]
[task 2021-07-13T20:57:46.777Z] 20:57:46 INFO - GECKO(1084) | [Parent 644: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (217fa848800) [pid = 644] [serial = 15] [outer = 0] [url = about:blank]
[task 2021-07-13T20:58:30.334Z] 20:58:30 INFO - GECKO(1084) | [Child 8200, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8525
[task 2021-07-13T20:58:30.338Z] 20:58:30 INFO - GECKO(1084) | [Child 8200, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8525
[task 2021-07-13T20:58:30.339Z] 20:58:30 INFO - GECKO(1084) | [Child 8200, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8525
[task 2021-07-13T20:59:03.535Z] 20:59:03 INFO - TEST-INFO | started process screenshot
[task 2021-07-13T20:59:03.596Z] 20:59:03 INFO - TEST-INFO | screenshot: exit 0
[task 2021-07-13T20:59:03.597Z] 20:59:03 INFO - Buffered messages logged at 20:57:33
[task 2021-07-13T20:59:03.597Z] 20:59:03 INFO - Entering test bound
[task 2021-07-13T20:59:03.598Z] 20:59:03 INFO - Event type: reorder. Target: [role: app root, name: 'Nightly', address: 0x217f51fb470]
[task 2021-07-13T20:59:03.598Z] 20:59:03 INFO - Buffered messages logged at 20:57:37
[task 2021-07-13T20:59:03.598Z] 20:59:03 INFO - Event type: reorder. Target: [role: app root, name: 'Nightly', address: 0x217f51fb470]
[task 2021-07-13T20:59:03.599Z] 20:59:03 INFO - Event type: text value change. Target: [DOM node id: urlbar-input, role: entry, name: 'Search with Google or enter address', address: 0x217f1f1b7c0]
[task 2021-07-13T20:59:03.599Z] 20:59:03 INFO - Event type: state change, state: busy, is enabled: false. Target: [role: document, name: 'New Tab', address: 0x217f19fe670]
[task 2021-07-13T20:59:03.599Z] 20:59:03 INFO - Event type: focus. Target: [role: document, address: 0x217f215e9d0]
[task 2021-07-13T20:59:03.600Z] 20:59:03 INFO - Event type: state change, state: busy, is enabled: true. Target: [role: document, address: 0x217f22608b0]
[task 2021-07-13T20:59:03.600Z] 20:59:03 INFO - Event type: focus. Target: [role: document, address: 0x217f22608b0]
[task 2021-07-13T20:59:03.601Z] 20:59:03 INFO - Event type: document load stopped. Target: [role: document, address: 0x217f22608b0]
[task 2021-07-13T20:59:03.601Z] 20:59:03 INFO - Event type: state change, state: busy, is enabled: false. Target: [role: document, address: 0x217f22608b0]
[task 2021-07-13T20:59:03.601Z] 20:59:03 INFO - TEST-PASS | accessible/tests/browser/states/browser_test_visibility.js | Actually remote browser -
[task 2021-07-13T20:59:03.602Z] 20:59:03 INFO - Buffered messages finished
[task 2021-07-13T20:59:03.602Z] 20:59:03 INFO - TEST-UNEXPECTED-FAIL | accessible/tests/browser/states/browser_test_visibility.js | Test timed out -
[task 2021-07-13T20:59:03.602Z] 20:59:03 INFO - GECKO(1084) | [Parent 644, Main Thread] WARNING: NS_ENSURE_TRUE(!IsDefunct()) failed: file /builds/worker/checkouts/gecko/accessible/windows/msaa/AccessibleWrap.cpp:81
[task 2021-07-13T20:59:03.624Z] 20:59:03 INFO - GECKO(1084) | MEMORY STAT | vsize 2104234MB | vsizeMaxContiguous 65406458MB | residentFast 259MB | heapAllocated 78MB
[task 2021-07-13T20:59:03.625Z] 20:59:03 INFO - TEST-OK | accessible/tests/browser/states/browser_test_visibility.js | took 90137ms
[task 2021-07-13T20:59:03.633Z] 20:59:03 INFO - GECKO(1084) | [Child 1984: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 1f2c1999800 == 1 [pid = 1984] [id = 2]
[task 2021-07-13T20:59:03.634Z] 20:59:03 INFO - GECKO(1084) | [Child 1984: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (1f2c88d5740) [pid = 1984] [serial = 6] [outer = 0]
[task 2021-07-13T20:59:03.634Z] 20:59:03 INFO - GECKO(1084) | [Child 1984: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (1f2c19a1000) [pid = 1984] [serial = 7] [outer = 1f2c88d5740]
[task 2021-07-13T20:59:03.662Z] 20:59:03 INFO - checking window state
[task 2021-07-13T20:59:03.705Z] 20:59:03 INFO - GECKO(1084) | [Parent 644: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 11 (217e4f8ac00) [pid = 644] [serial = 18] [outer = 217f6b46ac0]
[task 2021-07-13T20:59:03.728Z] 20:59:03 INFO - GECKO(1084) | [Parent 644, Main Thread] WARNING: NS_ENSURE_TRUE(presShell) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4223
[task 2021-07-13T20:59:03.786Z] 20:59:03 INFO - GECKO(1084) | [Child 4384: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 29c3a6bc400 == 0 [pid = 4384] [id = 1] [url = data:text/html;charset=utf-8,%3Chtml%3E%0A%20%20%20%20%20%20%3Chead%3E%0A%20%20%20%20%20%20%20%20%3Cmeta%20charset%3D%22utf-8%22%2F%3E%0A%20%20%20%20%20%20%20%20%3Ctitle%3EAccessibility%20Test%3C%2Ftitle%3E%0A%20%20%20%20%20%20%3C%2Fhead%3E%0A%20%20%20%20%20%20%3Cbody%20id%3D%22body%22%3E%0A%20%20%3Cdiv%20id%3D%22div%22%20style%3D%22border%3A2px%20solid%20blue%3B%20width%3A%20500px%3B%20height%3A%20110vh%3B%22%3E%3C%2Fdiv%3E%0A%20%20%3Cinput%20id%3D%22input_scrolledoff%22%3E%0A%20%20%3Cul%20style%3D%22border%3A2px%20solid%20red%3B%20width%3A%20100px%3B%20height%3A%2050px%3B%20overflow%3A%20auto%3B%22%3E%0A%20%20%20%20%3Cli%20id%3D%22li_first%22%3Eitem1%3C%2Fli%3E%3Cli%3Eitem2%3C%2Fli%3E%3Cli%3Eitem3%3C%2Fli%3E%0A%20%20%20%20%3Cli%3Eitem4%3C%2Fli%3E%3Cli%3Eitem5%3C%2Fli%3E%3Cli%20id%3D%22li_last%22%3Eitem6%3C%2Fli%3E%0A%20%20%3C%2Ful%3E%3C%2Fbody%3E%0A%20%20%20%20%3C%2Fhtml%3E]
[task 2021-07-13T20:59:03.791Z] 20:59:03 INFO - GECKO(1084) | [Child 10100: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 1e717646400 == 0 [pid = 10100] [id = 2] [url = about:blank]
[task 2021-07-13T20:59:03.812Z] 20:59:03 INFO - GECKO(1084) | [Child 4384: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (29c415d6e40) [pid = 4384] [serial = 4] [outer = 0] [url = data:text/html;charset=utf-8,%3Chtml%3E%0A%20%20%20%20%20%20%3Chead%3E%0A%20%20%20%20%20%20%20%20%3Cmeta%20charset%3D%22utf-8%22%2F%3E%0A%20%20%20%20%20%20%20%20%3Ctitle%3EAccessibility%20Test%3C%2Ftitle%3E%0A%20%20%20%20%20%20%3C%2Fhead%3E%0A%20%20%20%20%20%20%3Cbody%20id%3D%22body%22%3E%0A%20%20%3Cdiv%20id%3D%22div%22%20style%3D%22border%3A2px%20solid%20blue%3B%20width%3A%20500px%3B%20height%3A%20110vh%3B%22%3E%3C%2Fdiv%3E%0A%20%20%3Cinput%20id%3D%22input_scrolledoff%22%3E%0A%20%20%3Cul%20style%3D%22border%3A2px%20solid%20red%3B%20width%3A%20100px%3B%20height%3A%2050px%3B%20overflow%3A%20auto%3B%22%3E%0A%20%20%20%20%3Cli%20id%3D%22li_first%22%3Eitem1%3C%2Fli%3E%3Cli%3Eitem2%3C%2Fli%3E%3Cli%3Eitem3%3C%2Fli%3E%0A%20%20%20%20%3Cli%3Eitem4%3C%2Fli%3E%3Cli%3Eitem5%3C%2Fli%3E%3Cli%20id%3D%22li_last%22%3Eitem6%3C%2Fli%3E%0A%20%20%3C%2Ful%3E%3C%2Fbody%3E%0A%20%20%20%20%3C%2Fhtml%3E]
[task 2021-07-13T20:59:03.814Z] 20:59:03 INFO - GECKO(1084) | [Child 4384: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (29c43320000) [pid = 4384] [serial = 6] [outer = 0] [url = data:text/html;charset=utf-8,%3Chtml%3E%0A%20%20%20%20%20%20%3Chead%3E%0A%20%20%20%20%20%20%20%20%3Cmeta%20charset%3D%22utf-8%22%2F%3E%0A%20%20%20%20%20%20%20%20%3Ctitle%3EAccessibility%20Test%3C%2Ftitle%3E%0A%20%20%20%20%20%20%3C%2Fhead%3E%0A%20%20%20%20%20%20%3Cbody%20id%3D%22body%22%3E%0A%20%20%3Cdiv%20id%3D%22div%22%20style%3D%22border%3A2px%20solid%20blue%3B%20width%3A%20500px%3B%20height%3A%20110vh%3B%22%3E%3C%2Fdiv%3E%0A%20%20%3Cinput%20id%3D%22input_scrolledoff%22%3E%0A%20%20%3Cul%20style%3D%22border%3A2px%20solid%20red%3B%20width%3A%20100px%3B%20height%3A%2050px%3B%20overflow%3A%20auto%3B%22%3E%0A%20%20%20%20%3Cli%20id%3D%22li_first%22%3Eitem1%3C%2Fli%3E%3Cli%3Eitem2%3C%2Fli%3E%3Cli%3Eitem3%3C%2Fli%3E%0A%20%20%20%20%3Cli%3Eitem4%3C%2Fli%3E%3Cli%3Eitem5%3C%2Fli%3E%3Cli%20id%3D%22li_last%22%3Eitem6%3C%2Fli%3E%0A%20%20%3C%2Ful%3E%3C%2Fbody%3E%0A%20%20%20%20%3C%2Fhtml%3E]
[task 2021-07-13T20:59:03.885Z] 20:59:03 INFO - GECKO(1084) | [Child 8200: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (1c6093ce900) [pid = 8200] [serial = 1] [outer = 0] [url = about:newtab]
[task 2021-07-13T20:59:03.886Z] 20:59:03 INFO - GECKO(1084) | [Child 8200: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 1c60939d400 == 0 [pid = 8200] [id = 0] [url = about:newtab]
[task 2021-07-13T20:59:03.886Z] 20:59:03 INFO - GECKO(1084) | [Child 8200: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (1c60ac39800) [pid = 8200] [serial = 3] [outer = 0] [url = about:newtab]
[task 2021-07-13T20:59:04.420Z] 20:59:04 INFO - GECKO(1084) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-07-13T20:59:04.453Z] 20:59:04 INFO - GECKO(1084) | [Child 5388, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3357
[task 2021-07-13T20:59:04.471Z] 20:59:04 INFO - GECKO(1084) | [Child 5388, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4438
[task 2021-07-13T20:59:04.509Z] 20:59:04 INFO - GECKO(1084) | [Child 10100: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (1e717646800) [pid = 10100] [serial = 9] [outer = 0] [url = about:blank]
[task 2021-07-13T20:59:04.510Z] 20:59:04 INFO - GECKO(1084) | [Child 10100: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (1e715bf2ac0) [pid = 10100] [serial = 8] [outer = 0] [url = about:blank]
[task 2021-07-13T20:59:05.383Z] 20:59:05 INFO - GECKO(1084) | [Parent 644: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (217f897e400) [pid = 644] [serial = 8] [outer = 0] [url = about:blank]
[task 2021-07-13T20:59:05.579Z] 20:59:05 INFO - GECKO(1084) | Completed ShutdownLeaks collections in process 1984
[task 2021-07-13T20:59:05.586Z] 20:59:05 INFO - GECKO(1084) | Completed ShutdownLeaks collections in process 10100
[task 2021-07-13T20:59:05.589Z] 20:59:05 INFO - GECKO(1084) | Completed ShutdownLeaks collections in process 8200
[task 2021-07-13T20:59:05.598Z] 20:59:05 INFO - GECKO(1084) | Completed ShutdownLeaks collections in process 4384
[task 2021-07-13T20:59:05.753Z] 20:59:05 INFO - GECKO(1084) | Completed ShutdownLeaks collections in process 9944
[task 2021-07-13T20:59:05.761Z] 20:59:05 INFO - GECKO(1084) | [Parent 644, IPC I/O Parent] WARNING: file /builds/worker/checkouts/gecko/ipc/chromium/src/base/process_util_win.cc:167
[task 2021-07-13T20:59:05.770Z] 20:59:05 INFO - GECKO(1084) | [Parent 644: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 11 (217e4f41000) [pid = 644] [serial = 19] [outer = 217f6b46ac0]
[task 2021-07-13T20:59:07.675Z] 20:59:07 INFO - GECKO(1084) | [Parent 644: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (217e4f8ac00) [pid = 644] [serial = 18] [outer = 0] [url = about:blank]
[task 2021-07-13T20:59:08.041Z] 20:59:08 INFO - GECKO(1084) | Completed ShutdownLeaks collections in process 644
[task 2021-07-13T20:59:08.041Z] 20:59:08 INFO - TEST-START | Shutdown

Jamie are you still working on this?

Flags: needinfo?(jteh)
Whiteboard: [stockwell unknown] → [stockwell needswork:owner]

There are 37 total failures in the last 7 days on:

  • windows10-64-asan-qr
  • windows10-64-qr
  • windows10-64-shippable-qr

Recent failure log:
https://treeherder.mozilla.org/logviewer?job_id=346182099&repo=autoland&lineNumber=2127

Whiteboard: [stockwell needswork:owner] → [stockwell disabled]
Pushed by imoraru@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/f56a35aae0f7 disable browser_test_visibility.js on windows_10_64_qr for frequent failures. r=intermittent-reviewers,jmaher DONTBUILD
Summary: Intermittent accessible/tests/browser/states/browser_test_visibility.js | Test timed out - → Intermittent Windows accessible/tests/browser/states/browser_test_visibility.js | Test timed out -
Severity: normal → S3
Status: REOPENED → RESOLVED
Closed: 5 years ago3 years ago
Flags: needinfo?(jteh)
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: