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

Reporter

Description

•

5 years ago

treeherder

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 [task 2020-05-16T05:36:34.787Z] 05:36:34 [task 2020-05-16T05:36:34.788Z] 05:36:34 [task 2020-05-16T05:36:34.792Z] 05:36:34 [task 2020-05-16T05:36:34.800Z] 05:36:34 [task 2020-05-16T05:36:35.042Z] 05:36:35 [task 2020-05-16T05:36:35.042Z] 05:36:35 [task 2020-05-16T05:36:35.042Z] 05:36:35 [task 2020-05-16T05:36:35.042Z] 05:36:35 [task 2020-05-16T05:36:35.058Z] 05:36:35 [task 2020-05-16T05:36:35.059Z] 05:36:35 [task 2020-05-16T05:36:35.059Z] 05:36:35 [task 2020-05-16T05:36:35.126Z] 05:36:35 [task 2020-05-16T05:36:35.566Z] 05:36:35 [task 2020-05-16T05:36:35.566Z] 05:36:35 [task 2020-05-16T05:36:35.566Z] 05:36:35 [task 2020-05-16T05:36:35.567Z] 05:36:35 [task 2020-05-16T05:36:35.568Z] 05:36:35 [task 2020-05-16T05:36:35.568Z] 05:36:35 [task 2020-05-16T05:36:35.569Z] 05:36:35 [task 2020-05-16T05:36:35.570Z] 05:36:35 [task 2020-05-16T05:36:35.570Z] 05:36:35 [task 2020-05-16T05:36:35.572Z] 05:36:35 [task 2020-05-16T05:36:35.661Z] 05:36:35 [task 2020-05-16T05:36:35.662Z] 05:36:35 [task 2020-05-16T05:36:36.185Z] 05:36:36 [task 2020-05-16T05:36:36.186Z] 05:36:36 [task 2020-05-16T05:36:36.187Z] 05:36:36 [task 2020-05-16T05:36:36.187Z] 05:36:36 [task 2020-05-16T05:36:36.188Z] 05:36:36 [task 2020-05-16T05:36:36.197Z] 05:36:36 [task 2020-05-16T05:36:36.197Z] 05:36:36 [task 2020-05-16T05:36:36.218Z] 05:36:36 [task 2020-05-16T05:36:36.219Z] 05:36:36 [task 2020-05-16T05:36:36.220Z] 05:36:36 [task 2020-05-16T05:36:36.221Z] 05:36:36 [task 2020-05-16T05:36:36.229Z] 05:36:36 [task 2020-05-16T05:36:36.274Z] 05:36:36 [task 2020-05-16T05:36:36.289Z] 05:36:36 [task 2020-05-16T05:36:36.305Z] 05:36:36 [task 2020-05-16T05:36:36.319Z] 05:36:36 [task 2020-05-16T05:36:36.322Z] 05:36:36 [task 2020-05-16T05:36:40.088Z] 05:36:40 [task 2020-05-16T05:36:40.088Z] 05:36:40 [task 2020-05-16T05:36:40.088Z] 05:36:40 [task 2020-05-16T05:36:40.088Z] 05:36:40 [task 2020-05-16T05:36:40.088Z] 05:36:40 [task 2020-05-16T05:36:40.089Z] 05:36:40 [task 2020-05-16T05:36:40.089Z] 05:36:40 [task 2020-05-16T05:36:40.092Z] 05:36:40 [task 2020-05-16T05:36:40.092Z] 05:36:40 [task 2020-05-16T05:36:40.100Z] 05:36:40 [task 2020-05-16T05:36:40.100Z] 05:36:40 [task 2020-05-16T05:36:40.120Z] 05:36:40 [task 2020-05-16T05:36:40.253Z] 05:36:40 [task 2020-05-16T05:36:41.086Z] 05:36:41 [task 2020-05-16T05:36:41.088Z] 05:36:41 [task 2020-05-16T05:36:41.088Z] 05:36:41 [task 2020-05-16T05:36:41.088Z] 05:36:41 [task 2020-05-16T05:36:41.089Z] 05:36:41 [task 2020-05-16T05:36:41.089Z] 05:36:41 [task 2020-05-16T05:36:41.090Z] 05:36:41 [task 2020-05-16T05:36:41.091Z] 05:36:41 [task 2020-05-16T05:36:41.092Z] 05:36:41 [task 2020-05-16T05:36:41.092Z] 05:36:41 [task 2020-05-16T05:36:41.093Z] 05:36:41 [task 2020-05-16T05:36:41.093Z] 05:36:41 [task 2020-05-16T05:36:41.094Z] 05:36:41 INFO - TEST-START | remote/test/browser/network/browser_navigationEvents.js
INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7fc9e623b400 == 16 [pid = 4163] [id = {d56db603-9999-4438-999e-f6d6f8cd5929}]
INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 65 (0x7fc9e951d820) [pid = 4163] [serial = 96] [outer = (nil)]
INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 66 (0x7fc9e623f800) [pid = 4163] [serial = 97] [outer = 0x7fc9e951d820]
INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 67 (0x7fc9e623bc00) [pid = 4163] [serial = 98] [outer = 0x7fc9e951d820]
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
INFO - GECKO(4163) | [Parent 4163, Main Thread] WARNING: NS_ENSURE_TRUE(principal) failed: file /builds/worker/checkouts/gecko/extensions/permissions/Permission.cpp, line 58
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
INFO - GECKO(4163) | [Parent 4163, Main Thread] WARNING: NS_ENSURE_TRUE(principal) failed: file /builds/worker/checkouts/gecko/extensions/permissions/Permission.cpp, line 58
INFO - GECKO(4163) | [Child 4500: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7f1f81638c00 == 1 [pid = 4500] [id = {915f189d-7af4-4bac-b243-74033da0c4c4}]
INFO - GECKO(4163) | [Child 4500: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x7f1f9d193180) [pid = 4500] [serial = 7] [outer = (nil)]
INFO - GECKO(4163) | [Child 4500: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x7f1f8163a400) [pid = 4500] [serial = 8] [outer = 0x7f1f9d193180]
INFO - GECKO(4163) | [Child 4500: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (0x7f1f81694c00) [pid = 4500] [serial = 9] [outer = 0x7f1f9d193180]
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/]
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]
INFO - GECKO(4163) | [Child 4331: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 20 (0x7f66b7ddbc00) [pid = 4331] [serial = 54] [outer = (nil)] [url = about:blank]
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]
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/]
INFO - GECKO(4163) | [Child 4331: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 17 (0x7f66b7db6800) [pid = 4331] [serial = 58] [outer = (nil)] [url = about:blank]
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]
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/]
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]
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]
INFO - GECKO(4163) | [Child 4331: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 14 (0x7f66b05056f0) [pid = 4331] [serial = 60] [outer = (nil)] [url = http://example.org/foo/bar]
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]
INFO - GECKO(4163) | 1589607396179 RemoteAgent TRACE (connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18})-> {"id":1,"method":"Target.setDiscoverTargets","params":{"discover":true}}
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"}}}
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"}}}
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"}}}
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":{}}
INFO - GECKO(4163) | 1589607396191 RemoteAgent TRACE <-(connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18}) {"id":2}
INFO - GECKO(4163) | 1589607396193 RemoteAgent TRACE (connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18})-> {"id":3,"method":"Page.enable","params":{}}
INFO - GECKO(4163) | 1589607396212 RemoteAgent TRACE <-(connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18}) {"id":3}
INFO - GECKO(4163) | 1589607396213 RemoteAgent TRACE (connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18})-> {"id":4,"method":"Page.setLifecycleEventsEnabled","params":{"enabled":true}}
INFO - GECKO(4163) | 1589607396215 RemoteAgent TRACE <-(connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18}) {"id":4}
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"}}
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"}}
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"}}
INFO - GECKO(4163) | 1589607396280 RemoteAgent TRACE <-(connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18}) {"id":5,"result":{"frameId":"114","loaderId":"17879948853453"}}
INFO - GECKO(4163) | [Child 4500: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 4 (0x7f1f81699000) [pid = 4500] [serial = 10] [outer = 0x7f1f9d193180]
INFO - GECKO(4163) | 1589607396310 RemoteAgent TRACE <-(connection {255a925e-5ae2-4e4d-b7e3-7c4cc7bdbe18}) {"method":"Page.frameStartedLoading","params":{"frameId":"114"}}
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}}
INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc9e9a9b400 == 15 [pid = 4163] [id = {a6929699-fcc6-4d47-9131-75835326c562}] [url = about:blank]
INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc9ea81bc00 == 14 [pid = 4163] [id = {d4e64dbb-886e-411c-b59e-1e41a1d1eef3}] [url = about:blank]
INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc9f10af800 == 13 [pid = 4163] [id = {389e2edd-d871-430a-8f95-dabb6cc996bf}] [url = about:blank]
INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc9ea7bb800 == 12 [pid = 4163] [id = {6db75676-8a84-41ee-87f8-9ffe52ee8d13}] [url = about:blank]
INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc9e6433000 == 11 [pid = 4163] [id = {600349b2-6c0c-46de-8fcd-fe70f65ca4f8}] [url = about:blank]
INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc9e64ddc00 == 10 [pid = 4163] [id = {2d939eac-0fbe-4045-9d8b-8e84e98ea3b7}] [url = about:blank]
INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc9e64e6400 == 9 [pid = 4163] [id = {956dde3c-9567-43cb-b56d-04e6795fa482}] [url = about:blank]
INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc9e64ef400 == 8 [pid = 4163] [id = {4b41bf0b-93da-4ddc-ac99-90d6ffcfc418}] [url = about:blank]
INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc9e6430800 == 7 [pid = 4163] [id = {01798694-f02a-47d8-b387-f5465aba938a}] [url = about:blank]
INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 66 (0x7fc9ea756400) [pid = 4163] [serial = 47] [outer = (nil)] [url = about:blank]
INFO - GECKO(4163) | [Parent 4163: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 65 (0x7fc9ea7bb000) [pid = 4163] [serial = 44] [outer = (nil)] [url = about:blank]
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"}}}
INFO - TEST-INFO | started process screentopng[task 2020-05-16T05:36:41.086Z] 05:36:41 INFO - TEST-INFO | screentopng: exit 0
INFO - Buffered messages logged at 05:36:34
INFO - Entering test bound documentNavigationWithScriptResource
INFO - CDP server started
INFO - Buffered messages logged at 05:36:36
INFO - CDP client instantiated
INFO - Received Network.requestWillBeSent for http://example.com/browser/remote/test/browser/network/doc_networkEvents.html
INFO - Received Network.responseReceived for http://example.com/browser/remote/test/browser/network/doc_networkEvents.html
INFO - Recorded Page.navigate
INFO - TEST-PASS | remote/test/browser/network/browser_navigationEvents.js | Page.navigate returned a frameId -
INFO - Wait for events
INFO - Received Page.lifecycleEvent init
INFO - Buffered messages finished
INFO - TEST-UNEXPECTED-FAIL | remote/test/browser/network/browser_navigationEvents.js | Expected number of events - Got 4, expected 8

Henrik Skupin [:whimboo][⌚️UTC+2]

Assignee

Comment 1

•

5 years ago

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?

status-firefox77: --- → unaffected

status-firefox78: --- → affected

Flags: needinfo?(mjzffr)

Keywords: regression

Regressed by: 1599260

Comment hidden (Intermittent Failures Robot)

Henrik Skupin [:whimboo][⌚️UTC+2]

Assignee

Comment 4

•

5 years ago

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

Depends on: 1638196

Henrik Skupin [:whimboo][⌚️UTC+2]

Assignee

Updated

•

5 years ago

Flags: needinfo?(mjzffr)

Henrik Skupin [:whimboo][⌚️UTC+2]

Assignee

Comment 5

•

5 years ago

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

Assignee: nobody → hskupin

Status: NEW → RESOLVED

Closed: 5 years ago

status-firefox78: affected → fixed

Resolution: --- → FIXED

Target Milestone: --- → Firefox 78

Treeherder Bug Filer

Reporter

Updated

•

5 years ago

See Also: → https://bugzilla.mozilla.org/show_bug.cgi?id=1641872

Comment hidden (Intermittent Failures Robot)

Bugzilla

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

Categories

(Remote Protocol :: Agent, defect, P5)

Tracking

(firefox77 unaffected, firefox78 fixed)

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

Crash Data

Security

(public)

User Story

Description

Comment 1

Comment 2

Comment 3

Comment 4

Updated

Comment 5

Updated

Comment 6