1638518 - Intermittent remote/test/browser/network/browser_navigationEvents.js | Expected number of events - Got 4, expected 8

Status: RESOLVED FIXED

(Remote Protocol :: Agent, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-05-16T05:36:34.751Z] 05:36:34 INFO - TEST-START | remote/test/browser/network/browser_navigationEvents.js
[task 2020-05-16T05:36:34.787Z] 05:36:34 INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7fc9e623b400 == 16 [pid = 4163] [id = {d56db603-9999-4438-999e-f6d6f8cd5929}]
[task 2020-05-16T05:36:34.788Z] 05:36:34 INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 65 (0x7fc9e951d820) [pid = 4163] [serial = 96] [outer = (nil)]
[task 2020-05-16T05:36:34.792Z] 05:36:34 INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 66 (0x7fc9e623f800) [pid = 4163] [serial = 97] [outer = 0x7fc9e951d820]
[task 2020-05-16T05:36:34.800Z] 05:36:34 INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 67 (0x7fc9e623bc00) [pid = 4163] [serial = 98] [outer = 0x7fc9e951d820]
[task 2020-05-16T05:36:35.042Z] 05:36:35 INFO - GECKO(4163) | [Parent 4163, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, nullptr) failed with result 0x804B000A (NS_ERROR_MALFORMED_URI): file /builds/worker/checkouts/gecko/extensions/permissions/Permission.cpp, line 46
[task 2020-05-16T05:36:35.042Z] 05:36:35 INFO - GECKO(4163) | [Parent 4163, Main Thread] WARNING: NS_ENSURE_TRUE(principal) failed: file /builds/worker/checkouts/gecko/extensions/permissions/Permission.cpp, line 58
[task 2020-05-16T05:36:35.042Z] 05:36:35 INFO - GECKO(4163) | [Parent 4163, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, nullptr) failed with result 0x804B000A (NS_ERROR_MALFORMED_URI): file /builds/worker/checkouts/gecko/extensions/permissions/Permission.cpp, line 46
[task 2020-05-16T05:36:35.042Z] 05:36:35 INFO - GECKO(4163) | [Parent 4163, Main Thread] WARNING: NS_ENSURE_TRUE(principal) failed: file /builds/worker/checkouts/gecko/extensions/permissions/Permission.cpp, line 58
[task 2020-05-16T05:36:35.058Z] 05:36:35 INFO - GECKO(4163) | [Child 4500: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7f1f81638c00 == 1 [pid = 4500] [id = {915f189d-7af4-4bac-b243-74033da0c4c4}]
[task 2020-05-16T05:36:35.059Z] 05:36:35 INFO - GECKO(4163) | [Child 4500: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x7f1f9d193180) [pid = 4500] [serial = 7] [outer = (nil)]
[task 2020-05-16T05:36:35.059Z] 05:36:35 INFO - GECKO(4163) | [Child 4500: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x7f1f8163a400) [pid = 4500] [serial = 8] [outer = 0x7f1f9d193180]
[task 2020-05-16T05:36:35.126Z] 05:36:35 INFO - GECKO(4163) | [Child 4500: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (0x7f1f81694c00) [pid = 4500] [serial = 9] [outer = 0x7f1f9d193180]
[task 2020-05-16T05:36:35.566Z] 05:36:35 INFO - GECKO(4163) | [Child 4331: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 22 (0x7f66b0530000) [pid = 4331] [serial = 63] [outer = (nil)] [url = http://example.org/browser/remote/test/browser/network/sjs-cookies.sjs?name=foo&value=bar&path=/browser/remote/test/browser/]
[task 2020-05-16T05:36:35.566Z] 05:36:35 INFO - GECKO(4163) | [Child 4331: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 21 (0x7f66b7ddc000) [pid = 4331] [serial = 59] [outer = (nil)] [url = http://example.org/browser/remote/test/browser/network/sjs-cookies.sjs?name=foo&value=bar]
[task 2020-05-16T05:36:35.566Z] 05:36:35 INFO - GECKO(4163) | [Child 4331: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 20 (0x7f66b7ddbc00) [pid = 4331] [serial = 54] [outer = (nil)] [url = about:blank]
[task 2020-05-16T05:36:35.567Z] 05:36:35 INFO - GECKO(4163) | [Child 4331: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 19 (0x7f66b7e6cc00) [pid = 4331] [serial = 65] [outer = (nil)] [url = http://example.org/browser/remote/test/browser/network/sjs-cookies.sjs]
[task 2020-05-16T05:36:35.568Z] 05:36:35 INFO - GECKO(4163) | [Child 4331: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 18 (0x7f66b7e6f800) [pid = 4331] [serial = 66] [outer = (nil)] [url = http://example.org/browser/remote/test/]
[task 2020-05-16T05:36:35.568Z] 05:36:35 INFO - GECKO(4163) | [Child 4331: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 17 (0x7f66b7db6800) [pid = 4331] [serial = 58] [outer = (nil)] [url = about:blank]
[task 2020-05-16T05:36:35.569Z] 05:36:35 INFO - GECKO(4163) | [Child 4331: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 16 (0x7f66b0530800) [pid = 4331] [serial = 55] [outer = (nil)] [url = http://example.org/browser/remote/test/browser/network/sjs-cookies.sjs?name=foo&value=bar&expiry=Tue,%2019%20May%202020%2005:36:23%20GMT]
[task 2020-05-16T05:36:35.570Z] 05:36:35 INFO - GECKO(4163) | [Child 4331: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 15 (0x7f66b7dd9400) [pid = 4331] [serial = 64] [outer = (nil)] [url = http://example.org/browser/remote/test/browser/]
[task 2020-05-16T05:36:35.570Z] 05:36:35 INFO - GECKO(4163) | [Child 4331: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f66b7ddcc00 == 3 [pid = 4331] [id = {1e300bbc-fcd6-48bf-a67b-109934a76aca}] [url = http://example.org/foo/bar]
[task 2020-05-16T05:36:35.572Z] 05:36:35 INFO - GECKO(4163) | [Child 4331: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f66b052ac00 == 2 [pid = 4331] [id = {2a59bad1-0887-4301-a03f-e93b917ba149}] [url = http://example.org/browser/remote/test/browser/network/sjs-cookies.sjs?name=foo&value=bar&httpOnly]
[task 2020-05-16T05:36:35.661Z] 05:36:35 INFO - GECKO(4163) | [Child 4331: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 14 (0x7f66b05056f0) [pid = 4331] [serial = 60] [outer = (nil)] [url = http://example.org/foo/bar]
[task 2020-05-16T05:36:35.662Z] 05:36:35 INFO - GECKO(4163) | [Child 4331: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 13 (0x7f66b0502600) [pid = 4331] [serial = 68] [outer = (nil)] [url = http://example.org/browser/remote/test/browser/network/sjs-cookies.sjs?name=foo&value=bar&httpOnly]
[task 2020-05-16T05:36:36.185Z] 05:36:36 INFO - GECKO(4163) | 1589607396179 RemoteAgent TRACE (connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18})-> {"id":1,"method":"Target.setDiscoverTargets","params":{"discover":true}}
[task 2020-05-16T05:36:36.186Z] 05:36:36 INFO - GECKO(4163) | 1589607396180 RemoteAgent TRACE <-(connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18}) {"method":"Target.targetCreated","params":{"targetInfo":{"browserContextId":null,"targetId":"f99e3348-bd5e-44e1-b971-d47bba871285","type":"page","url":"about:blank"}}}
[task 2020-05-16T05:36:36.187Z] 05:36:36 INFO - GECKO(4163) | 1589607396180 RemoteAgent TRACE <-(connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18}) {"method":"Target.targetCreated","params":{"targetInfo":{"targetId":"f04314b3-59b9-4b1c-9d8d-d396b3c849f8","type":"browser"}}}
[task 2020-05-16T05:36:36.187Z] 05:36:36 INFO - GECKO(4163) | 1589607396181 RemoteAgent TRACE <-(connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18}) {"method":"Target.targetCreated","params":{"targetInfo":{"browserContextId":null,"targetId":"b9289cb7-610b-40e4-99d2-0626652bf0f4","type":"page","url":"about:blank"}}}
[task 2020-05-16T05:36:36.188Z] 05:36:36 INFO - GECKO(4163) | 1589607396181 RemoteAgent TRACE <-(connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18}) {"id":1}[task 2020-05-16T05:36:36.196Z] 05:36:36 INFO - GECKO(4163) | 1589607396191 RemoteAgent TRACE (connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18})-> {"id":2,"method":"Network.enable","params":{}}
[task 2020-05-16T05:36:36.197Z] 05:36:36 INFO - GECKO(4163) | 1589607396191 RemoteAgent TRACE <-(connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18}) {"id":2}
[task 2020-05-16T05:36:36.197Z] 05:36:36 INFO - GECKO(4163) | 1589607396193 RemoteAgent TRACE (connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18})-> {"id":3,"method":"Page.enable","params":{}}
[task 2020-05-16T05:36:36.218Z] 05:36:36 INFO - GECKO(4163) | 1589607396212 RemoteAgent TRACE <-(connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18}) {"id":3}
[task 2020-05-16T05:36:36.219Z] 05:36:36 INFO - GECKO(4163) | 1589607396213 RemoteAgent TRACE (connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18})-> {"id":4,"method":"Page.setLifecycleEventsEnabled","params":{"enabled":true}}
[task 2020-05-16T05:36:36.220Z] 05:36:36 INFO - GECKO(4163) | 1589607396215 RemoteAgent TRACE <-(connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18}) {"id":4}
[task 2020-05-16T05:36:36.221Z] 05:36:36 INFO - GECKO(4163) | 1589607396218 RemoteAgent TRACE (connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18})-> {"id":5,"method":"Page.navigate","params":{"url":"http://example.com/browser/remote/test/browser/network/doc_networkEvents.html"}}
[task 2020-05-16T05:36:36.229Z] 05:36:36 INFO - GECKO(4163) | 1589607396224 RemoteAgent TRACE <-(connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18}) {"method":"Network.requestWillBeSent","params":{"requestId":"17879948853453","loaderId":"17879948853453","documentURL":"http: ... tion":"keep-alive"},"hasPostData":false,"isLinkPreload":false},"timestamp":1589607396.224,"type":"Document","frameId":"114"}}
[task 2020-05-16T05:36:36.274Z] 05:36:36 INFO - GECKO(4163) | 1589607396264 RemoteAgent TRACE <-(connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18}) {"method":"Network.responseReceived","params":{"requestId":"17879948853453","loaderId":"17879948853453","timestamp":158960739 ... otePort":8888,"fromDiskCache":false,"protocol":"http/1.1","securityDetails":null,"securityState":"unknown"},"frameId":"114"}}
[task 2020-05-16T05:36:36.289Z] 05:36:36 INFO - GECKO(4163) | 1589607396280 RemoteAgent TRACE <-(connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18}) {"id":5,"result":{"frameId":"114","loaderId":"17879948853453"}}
[task 2020-05-16T05:36:36.305Z] 05:36:36 INFO - GECKO(4163) | [Child 4500: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 4 (0x7f1f81699000) [pid = 4500] [serial = 10] [outer = 0x7f1f9d193180]
[task 2020-05-16T05:36:36.319Z] 05:36:36 INFO - GECKO(4163) | 1589607396310 RemoteAgent TRACE <-(connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18}) {"method":"Page.frameStartedLoading","params":{"frameId":"114"}}
[task 2020-05-16T05:36:36.322Z] 05:36:36 INFO - GECKO(4163) | 1589607396310 RemoteAgent TRACE <-(connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18}) {"method":"Page.lifecycleEvent","params":{"frameId":"114","loaderId":"17879948853453","name":"init","timestamp":1589607396.292}}
[task 2020-05-16T05:36:40.088Z] 05:36:40 INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc9e9a9b400 == 15 [pid = 4163] [id = {a6929699-fcc6-4d47-9131-75835326c562}] [url = about:blank]
[task 2020-05-16T05:36:40.088Z] 05:36:40 INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc9ea81bc00 == 14 [pid = 4163] [id = {d4e64dbb-886e-411c-b59e-1e41a1d1eef3}] [url = about:blank]
[task 2020-05-16T05:36:40.088Z] 05:36:40 INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc9f10af800 == 13 [pid = 4163] [id = {389e2edd-d871-430a-8f95-dabb6cc996bf}] [url = about:blank]
[task 2020-05-16T05:36:40.088Z] 05:36:40 INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc9ea7bb800 == 12 [pid = 4163] [id = {6db75676-8a84-41ee-87f8-9ffe52ee8d13}] [url = about:blank]
[task 2020-05-16T05:36:40.088Z] 05:36:40 INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc9e6433000 == 11 [pid = 4163] [id = {600349b2-6c0c-46de-8fcd-fe70f65ca4f8}] [url = about:blank]
[task 2020-05-16T05:36:40.089Z] 05:36:40 INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc9e64ddc00 == 10 [pid = 4163] [id = {2d939eac-0fbe-4045-9d8b-8e84e98ea3b7}] [url = about:blank]
[task 2020-05-16T05:36:40.089Z] 05:36:40 INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc9e64e6400 == 9 [pid = 4163] [id = {956dde3c-9567-43cb-b56d-04e6795fa482}] [url = about:blank]
[task 2020-05-16T05:36:40.092Z] 05:36:40 INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc9e64ef400 == 8 [pid = 4163] [id = {4b41bf0b-93da-4ddc-ac99-90d6ffcfc418}] [url = about:blank]
[task 2020-05-16T05:36:40.092Z] 05:36:40 INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc9e6430800 == 7 [pid = 4163] [id = {01798694-f02a-47d8-b387-f5465aba938a}] [url = about:blank]
[task 2020-05-16T05:36:40.100Z] 05:36:40 INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 66 (0x7fc9ea756400) [pid = 4163] [serial = 47] [outer = (nil)] [url = about:blank]
[task 2020-05-16T05:36:40.100Z] 05:36:40 INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 65 (0x7fc9ea7bb000) [pid = 4163] [serial = 44] [outer = (nil)] [url = about:blank]
[task 2020-05-16T05:36:40.120Z] 05:36:40 INFO - GECKO(4163) | 1589607400117 RemoteAgent TRACE <-(connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18}) {"method":"Page.frameNavigated","params":{"frame":{"id":"114","parentId":null,"url":"http://example.com/browser/remote/test/browser/network/doc_networkEvents.html"}}}
[task 2020-05-16T05:36:40.253Z] 05:36:40 INFO - TEST-INFO | started process screentopng[task 2020-05-16T05:36:41.086Z] 05:36:41 INFO - TEST-INFO | screentopng: exit 0
[task 2020-05-16T05:36:41.086Z] 05:36:41 INFO - Buffered messages logged at 05:36:34
[task 2020-05-16T05:36:41.088Z] 05:36:41 INFO - Entering test bound documentNavigationWithScriptResource
[task 2020-05-16T05:36:41.088Z] 05:36:41 INFO - CDP server started
[task 2020-05-16T05:36:41.088Z] 05:36:41 INFO - Buffered messages logged at 05:36:36
[task 2020-05-16T05:36:41.089Z] 05:36:41 INFO - CDP client instantiated
[task 2020-05-16T05:36:41.089Z] 05:36:41 INFO - Received Network.requestWillBeSent for http://example.com/browser/remote/test/browser/network/doc_networkEvents.html
[task 2020-05-16T05:36:41.090Z] 05:36:41 INFO - Received Network.responseReceived for http://example.com/browser/remote/test/browser/network/doc_networkEvents.html
[task 2020-05-16T05:36:41.091Z] 05:36:41 INFO - Recorded Page.navigate
[task 2020-05-16T05:36:41.092Z] 05:36:41 INFO - TEST-PASS | remote/test/browser/network/browser_navigationEvents.js | Page.navigate returned a frameId -
[task 2020-05-16T05:36:41.092Z] 05:36:41 INFO - Wait for events
[task 2020-05-16T05:36:41.093Z] 05:36:41 INFO - Received Page.lifecycleEvent init
[task 2020-05-16T05:36:41.093Z] 05:36:41 INFO - Buffered messages finished
[task 2020-05-16T05:36:41.094Z] 05:36:41 INFO - TEST-UNEXPECTED-FAIL | remote/test/browser/network/browser_navigationEvents.js | Expected number of events - Got 4, expected 8

Comment 1

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

Maja, the log shows a lot of failure:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=302557591&repo=autoland&lineNumber=7618

Could you please have a look at these?

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux1804-64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1638518&startday=2020-05-11&endday=2020-05-17&tree=all

Comment 3

[Intermittent Failures Robot]

12 failures in 4727 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 11
• try: 1

Platform breakdown:

• linux1804-64-qr: 4
• linux1804-64: 7
• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1638518&startday=2020-05-18&endday=2020-05-24&tree=all

Comment 4

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

Failure on Ubuntu 18.04 only. Might be fixed with the patch on bug 1638196.

Comment 5

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

This looks to be fixed now by my patch on bug 1638196.

Comment 6

[Intermittent Failures Robot]

5 failures in 5458 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 4
• mozilla-central: 1

Platform breakdown:

• linux1804-64-qr: 4
• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1638518&startday=2020-05-25&endday=2020-05-31&tree=all