1772011 - Intermittent remote/cdp/test/browser/page/browser_navigate.js | Test timed out -

Status: RESOLVED DUPLICATE of bug 1776024

(Remote Protocol :: CDP, defect, P5)

Description

[Treeherder Bug Filer]

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

---

 INFO - TEST-PASS | remote/cdp/test/browser/page/browser_navigate.js | Page.navigate returns loaderId - 
[task 2022-05-31T20:48:36.398Z] 20:48:36     INFO - Check that Page.navigate can navigate to an anchor
[task 2022-05-31T20:48:36.399Z] 20:48:36     INFO - Buffered messages logged at 20:47:03
[task 2022-05-31T20:48:36.405Z] 20:48:36     INFO - Console message: [JavaScript Error: "Invalid ETag value "undefined"" {file: "resource://services-settings/SyncHistory.jsm" line: 50}]
[task 2022-05-31T20:48:36.408Z] 20:48:36     INFO - store@resource://services-settings/SyncHistory.jsm:50:13
[task 2022-05-31T20:48:36.409Z] 20:48:36     INFO - 
[task 2022-05-31T20:48:36.410Z] 20:48:36     INFO - Buffered messages finished
[task 2022-05-31T20:48:36.410Z] 20:48:36     INFO - TEST-UNEXPECTED-FAIL | remote/cdp/test/browser/page/browser_navigate.js | Test timed out - 
[task 2022-05-31T20:48:36.411Z] 20:48:36     INFO - GECKO(5093) | 1654030115963	RemoteAgent	DEBUG	CDPConnection 147ac161-238b-46f0-8574-f2ab1f76d5b8 closed
[task 2022-05-31T20:48:36.412Z] 20:48:36     INFO - GECKO(5093) | MEMORY STAT | vsize 20975641MB | residentFast 1637MB
[task 2022-05-31T20:48:36.412Z] 20:48:36     INFO - TEST-OK | remote/cdp/test/browser/page/browser_navigate.js | took 180108ms

Comment 1

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

The hang is earlier and was close to 3 minutes:
https://treeherder.mozilla.org/logviewer?job_id=379800498&repo=mozilla-beta&lineNumber=28263-28273

[task 2022-05-31T20:45:49.794Z] 20:45:49     INFO - GECKO(5093) | 1654029949793	CDP	TRACE	CDPConnection 147ac161-238b-46f0-8574-f2ab1f76d5b8 -> {"id":4,"method":"Page.navigate","params":{"url":"https://example.com/browser/remote/cdp/test/browser/page/doc_empty.html#hash"}}
[task 2022-05-31T20:45:49.897Z] 20:45:49     INFO - GECKO(5093) | 1654029949896	CDP	TRACE	CDPConnection 147ac161-238b-46f0-8574-f2ab1f76d5b8 <- {"method":"Page.navigatedWithinDocument","params":{"frameId":"424","url":"https://example.com/browser/remote/cdp/test/browser/page/doc_empty.html#hash"}}
[task 2022-05-31T20:45:49.899Z] 20:45:49     INFO - GECKO(5093) | 1654029949898	CDP	TRACE	CDPConnection 147ac161-238b-46f0-8574-f2ab1f76d5b8 <- {"method":"Page.frameNavigated","params":{"frame":{"id":"424","loaderId":"10937134219899","url":"https://example.com/browser/remote/cdp/test/browser/page/doc_empty.html#hash","securityOrigin":null,"mimeType":null}}}
[task 2022-05-31T20:45:49.905Z] 20:45:49     INFO - GECKO(5093) | 1654029949904	CDP	TRACE	CDPConnection 147ac161-238b-46f0-8574-f2ab1f76d5b8 <- {"method":"Page.domContentEventFired","params":{"timestamp":1654029949.819}}
[task 2022-05-31T20:45:49.907Z] 20:45:49     INFO - GECKO(5093) | 1654029949906	CDP	TRACE	CDPConnection 147ac161-238b-46f0-8574-f2ab1f76d5b8 <- {"method":"Page.loadEventFired","params":{"timestamp":1654029949.822}}
[task 2022-05-31T20:45:49.909Z] 20:45:49     INFO - GECKO(5093) | 1654029949908	CDP	TRACE	CDPConnection 147ac161-238b-46f0-8574-f2ab1f76d5b8 <- {"method":"Page.frameStoppedLoading","params":{"frameId":"424"}}
[task 2022-05-31T20:48:35.925Z] 20:48:35     INFO - TEST-INFO | started process screentopng
[task 2022-05-31T20:48:36.244Z] 20:48:36     INFO - TEST-INFO | screentopng: exit 0
[task 2022-05-31T20:48:36.244Z] 20:48:36     INFO - <snipped 4 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2022-05-31T20:48:36.245Z] 20:48:36     INFO - Buffered messages logged at 20:45:36
[task 2022-05-31T20:48:36.245Z] 20:48:36     INFO - TEST-PASS | remote/cdp/test/browser/page/browser_navigate.js | No errorText on a successful navigation - 

So it happened after a successful navigation and the final Page.frameStoppedLoading event has been sent out as well. Sadly there are 4 snipped output lines which might have been interesting to know what was happening. Lets continue to observe.

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1
• try: 1

Platform and build breakdown:

• linux1804-64-asan-qr: 1
  • opt: 1
• linux1804-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1772011&startday=2022-05-30&endday=2022-06-05&tree=all

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-asan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1772011&startday=2022-06-06&endday=2022-06-12&tree=all

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-ccov-qr: 1
  • opt: 1

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