Open Bug 1703692 Opened 2 months ago Updated 1 day ago

Intermittent browser/components/sessionstore/test/browser_formdata.js | Uncaught exception - at /browser/components/sessionstore/test/browser_formdata.js:48 - TypeError: can't access property 0, formdata.children is undefined

Categories

(Firefox :: Session Restore, defect, P3)

defect

Tracking

()

ASSIGNED
Fission Milestone M7a

People

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

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure)

Attachments

(1 obsolete file)

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


[task 2021-04-07T21:18:18.594Z] 21:18:18     INFO - TEST-START | browser/components/sessionstore/test/browser_formdata.js
[task 2021-04-07T21:18:18.630Z] 21:18:18     INFO - GECKO(7216) | [Child 10565: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (7f254ae63c80) [pid = 10565] [serial = 1] [outer = 0] [url = http://example.com/]
[task 2021-04-07T21:18:18.630Z] 21:18:18     INFO - GECKO(7216) | [Child 10565: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (7f2534992800) [pid = 10565] [serial = 2] [outer = 0] [url = about:blank]
[task 2021-04-07T21:18:18.630Z] 21:18:18     INFO - GECKO(7216) | [Child 10565: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (7f2534999800) [pid = 10565] [serial = 3] [outer = 0] [url = http://example.com/]
[task 2021-04-07T21:18:18.630Z] 21:18:18     INFO - GECKO(7216) | [Child 10565, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3361
[task 2021-04-07T21:18:18.634Z] 21:18:18     INFO - GECKO(7216) | [Child 10565, Main Thread] WARNING: '!obs', file /builds/worker/checkouts/gecko/toolkit/components/sessionstore/RestoreTabContentObserver.cpp:58
[task 2021-04-07T21:18:18.635Z] 21:18:18     INFO - GECKO(7216) | [Child 10609: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7f608e299400 == 1 [pid = 10609] [id = 0]
[task 2021-04-07T21:18:18.636Z] 21:18:18     INFO - GECKO(7216) | [Child 10609: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (7f60a4763c80) [pid = 10609] [serial = 1] [outer = 0]
[task 2021-04-07T21:18:18.638Z] 21:18:18     INFO - GECKO(7216) | [Child 10609: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (7f608e29a400) [pid = 10609] [serial = 2] [outer = 7f60a4763c80]
[task 2021-04-07T21:18:18.680Z] 21:18:18     INFO - GECKO(7216) | [Child 10565, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4442
[task 2021-04-07T21:18:18.803Z] 21:18:18     INFO - GECKO(7216) | [Child 9455: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (7fd43a919580) [pid = 9455] [serial = 26] [outer = 0] [url = about:newtab]
[task 2021-04-07T21:18:18.819Z] 21:18:18     INFO - GECKO(7216) | [Child 10609, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp:348
[task 2021-04-07T21:18:18.820Z] 21:18:18     INFO - GECKO(7216) | [Child 10609: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (7f60880b7400) [pid = 10609] [serial = 3] [outer = 7f60a4763c80]
[task 2021-04-07T21:18:18.904Z] 21:18:18     INFO - GECKO(7216) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpi4NiA6.mozrunner/runtests_leaks_tab_pid10697.log
[task 2021-04-07T21:18:18.905Z] 21:18:18     INFO - GECKO(7216) | [10697, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:254
[task 2021-04-07T21:18:18.982Z] 21:18:18     INFO - GECKO(7216) | [Child 10697, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:619
[task 2021-04-07T21:18:19.111Z] 21:18:19     INFO - GECKO(7216) | [Child 10609: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7f60880be800 == 2 [pid = 10609] [id = 1]
[task 2021-04-07T21:18:19.111Z] 21:18:19     INFO - GECKO(7216) | [Child 10609: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 4 (7f60a4763e40) [pid = 10609] [serial = 4] [outer = 0]
[task 2021-04-07T21:18:19.112Z] 21:18:19     INFO - GECKO(7216) | [Child 10609: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 5 (7f60880c0000) [pid = 10609] [serial = 5] [outer = 7f60a4763e40]
[task 2021-04-07T21:18:19.177Z] 21:18:19     INFO - GECKO(7216) | [Child 10614: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7f1e93c96400 == 1 [pid = 10614] [id = 0]
[task 2021-04-07T21:18:19.178Z] 21:18:19     INFO - GECKO(7216) | [Child 10614: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (7f1eaa163c80) [pid = 10614] [serial = 1] [outer = 0]
[task 2021-04-07T21:18:19.179Z] 21:18:19     INFO - GECKO(7216) | [Child 10614: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (7f1e93c97400) [pid = 10614] [serial = 2] [outer = 7f1eaa163c80]
[task 2021-04-07T21:18:19.218Z] 21:18:19     INFO - GECKO(7216) | [Child 10614: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (7f1e8dab6800) [pid = 10614] [serial = 3] [outer = 7f1eaa163c80]
[task 2021-04-07T21:18:19.420Z] 21:18:19     INFO - GECKO(7216) | [Child 10282: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (7f0cea8a4800) [pid = 10282] [serial = 29] [outer = 0] [url = data:text/html;charset=utf-8,<iframe name=t src='data:text/html,A'></iframe><a id=lnk href='data:text/html,B' target=t>clickme</a><script>var i=document.createElement('iframe');i.setAttribute('src', 'data:text/html,C');document.body.appendChild(i);</script>]
[task 2021-04-07T21:18:19.420Z] 21:18:19     INFO - GECKO(7216) | [Child 10282: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (7f0cea8a9400) [pid = 10282] [serial = 32] [outer = 0] [url = data:text/html,A]
[task 2021-04-07T21:18:19.420Z] 21:18:19     INFO - GECKO(7216) | [Child 10282: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 9 (7f0ceb6be400) [pid = 10282] [serial = 33] [outer = 0] [url = data:text/html,C]
[task 2021-04-07T21:18:19.420Z] 21:18:19     INFO - GECKO(7216) | [Child 10282: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 8 (7f0ceb6ca400) [pid = 10282] [serial = 34] [outer = 0] [url = data:text/html,B]
[task 2021-04-07T21:18:19.422Z] 21:18:19     INFO - GECKO(7216) | [Child 10282: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 7 (7f0ceb6ccc00) [pid = 10282] [serial = 39] [outer = 0] [url = about:blank]
[task 2021-04-07T21:18:19.425Z] 21:18:19     INFO - GECKO(7216) | [Child 10282: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 6 (7f0cea8a4c00) [pid = 10282] [serial = 38] [outer = 0] [url = about:blank]
[task 2021-04-07T21:18:19.425Z] 21:18:19     INFO - GECKO(7216) | [Child 10282: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 5 (7f0cea8a1000) [pid = 10282] [serial = 36] [outer = 0] [url = about:blank]
[task 2021-04-07T21:18:19.426Z] 21:18:19     INFO - GECKO(7216) | [Child 10282: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f0cea89c400 == 1 [pid = 10282] [id = 16] [url = about:blank]
[task 2021-04-07T21:18:19.502Z] 21:18:19     INFO - GECKO(7216) | [Child 10282: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (7f0cea807200) [pid = 10282] [serial = 40] [outer = 0] [url = about:blank]
[task 2021-04-07T21:18:19.503Z] 21:18:19     INFO - GECKO(7216) | [Child 10614: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7f1e8dabd800 == 2 [pid = 10614] [id = 1]
[task 2021-04-07T21:18:19.503Z] 21:18:19     INFO - GECKO(7216) | [Child 10614: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 4 (7f1e8d13f040) [pid = 10614] [serial = 4] [outer = 0]
[task 2021-04-07T21:18:19.510Z] 21:18:19     INFO - GECKO(7216) | [Child 10614: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 5 (7f1e8dabf000) [pid = 10614] [serial = 5] [outer = 7f1e8d13f040]
[task 2021-04-07T21:18:19.560Z] 21:18:19     INFO - GECKO(7216) | [Child 7280: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (7fb1feac5000) [pid = 7280] [serial = 333] [outer = 0] [url = about:blank]
[task 2021-04-07T21:18:19.576Z] 21:18:19     INFO - GECKO(7216) | [Child 7280: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7fb1feabd400 == 0 [pid = 7280] [id = 152] [url = about:blank]
[task 2021-04-07T21:18:19.654Z] 21:18:19     INFO - GECKO(7216) | updateSessionStoreFromTablistener() with aData.sHistoryNeeded, but no SHlistener. Add again!!!JavaScript error: resource:///modules/sessionstore/SessionStore.jsm, line 1091: Error: no SessionHistory object
[task 2021-04-07T21:18:19.654Z] 21:18:19     INFO - GECKO(7216) | [Parent 7216, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, mozilla::ipc::IPCResult::Ok()) failed with result 0x80570021 (NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS): file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:2918
[task 2021-04-07T21:18:19.655Z] 21:18:19     INFO - TEST-INFO | started process screentopng
[task 2021-04-07T21:18:20.055Z] 21:18:20     INFO - TEST-INFO | screentopng: exit 0
[task 2021-04-07T21:18:20.055Z] 21:18:20     INFO - Buffered messages logged at 21:18:18
[task 2021-04-07T21:18:20.055Z] 21:18:20     INFO - Entering test bound test_formdata
[task 2021-04-07T21:18:20.055Z] 21:18:20     INFO - Buffered messages logged at 21:18:19
[task 2021-04-07T21:18:20.055Z] 21:18:20     INFO - TEST-PASS | browser/components/sessionstore/test/browser_formdata.js | outer value is correct - 
[task 2021-04-07T21:18:20.055Z] 21:18:20     INFO - Buffered messages finished
[task 2021-04-07T21:18:20.055Z] 21:18:20     INFO - TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_formdata.js | Uncaught exception - at chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_formdata.js:48 - TypeError: can't access property 0, formdata.children is undefined
[task 2021-04-07T21:18:20.055Z] 21:18:20     INFO - Stack trace:
[task 2021-04-07T21:18:20.055Z] 21:18:20     INFO - test_formdata@chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_formdata.js:48:3
[task 2021-04-07T21:18:20.055Z] 21:18:20     INFO - Leaving test bound test_formdata```
Assignee: nobody → kmadan
Status: NEW → ASSIGNED
Attachment #9218754 - Attachment is obsolete: true
Fission Milestone: --- → M7a
Depends on: 1706445

The problem here is that we're checking the collected data before the subframe's nsFrameLoader::StartDestroy flush has finished. This has become more apparent with the patches from bug 1706445, and this will probably be fixed in that bug.

Blocks: 1715264
No longer blocks: fission-sessionstore
No longer blocks: 1715264
See Also: → 1715264

(In reply to :kashav from comment #7)

The problem here is that we're checking the collected data before the subframe's nsFrameLoader::StartDestroy flush has finished.

The problem is that we fail to get an owner element for subframe WindowGlobalParents when doing the final flush, and so we occasionally don't get an update for those frames. Might need to hold on to the owner element while a tab close flush is in progress.

So looks like we're racing between BrowserParent::ActorDestroy and non-toplevel WindowGlobalParent::RecvUpdateSessionStore. I wonder if it would be fine to wait for another event loop in BrowserChild::DelayedDeleteRunnable.

nika, any ideas for how to deal with this?

We're clearing BrowserParent::OwnerElement before we receive all flushes, so we sometimes don't have a frameElement here.

pernosco trace: https://pernos.co/debug/Bw0sExqwbOTU46w2I62xBA/index.html#f{m[Ahz8,AA_,t[AQ,CDs_,f{e[Ahz5,QxMo_,s{af6x3f5AA,bARY,uINHj,oIW5a___

Flags: needinfo?(nika)

I think the ideal fix in a situation like this is probably to avoid having sessionstore depending on the browser element itself, and instead depending on the BrowserId or similar, so that we don't need to worry about that particular attribute being cleared.

Potentially we can get away with some other fix here though, I suppose. What attributes are we needing from the <browser> itself? Could we get away with just keeping around the .permanentKey?

So looks like we're racing between BrowserParent::ActorDestroy and non-toplevel WindowGlobalParent::RecvUpdateSessionStore. I wonder if it would be fine to wait for another event loop in BrowserChild::DelayedDeleteRunnable.

That wouldn't help, as there's no guarantee of ordering between the toplevel BrowserChild instance and messages to any other process. If we want to handle this here, we have to deal with the BrowserParent::ActorDestroy already being called before we finish receiving sessionstore updates.

Flags: needinfo?(nika)
Severity: S4 → S3
Priority: P5 → P3
See Also: → 1716788
You need to log in before you can comment on or make changes to this bug.