1674939 - Perma Tier 2 TEST-UNEXPECTED-TIMEOUT | navigation Frame.goto should return matching responses (navigation.spec.ts) | expected FAILTEST-UNEXPECTED-TIMEOUT | Page Page.close should run beforeunload if asked for (page.spec.ts) | expected FAIL

Status: RESOLVED FIXED

(Remote Protocol :: Agent, defect, P5)

Description

[Treeherder Bug Filer]

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

---

...
[task 2020-11-02T23:41:57.130Z] PID 352 | 1604360517129	RemoteAgent	TRACE	(connection {412c5d14-de93-459d-b253-a67433f172e7})-> {"sessionId":"a9180294-d34b-4bc5-aa86-501d0beca82c","method":"DOM.describeNode","params":{"objectId":"08f927f9-6309-457e-bd77-acb1c1fe4a7f"},"id":1197}
[task 2020-11-02T23:41:57.131Z] PID 352 | 1604360517130	RemoteAgent	TRACE	(connection {412c5d14-de93-459d-b253-a67433f172e7})-> {"sessionId":"a9180294-d34b-4bc5-aa86-501d0beca82c","method":"DOM.describeNode","params":{"objectId":"b6d088a4-e56c-475b-a223-0287875c9a7d"},"id":1198}
[task 2020-11-02T23:41:57.131Z] PID 352 | 1604360517130	RemoteAgent	TRACE	<-(connection {412c5d14-de93-459d-b253-a67433f172e7}) {"sessionId":"a9180294-d34b-4bc5-aa86-501d0beca82c","method":"Page.frameStoppedLoading","params":{"frameId":"45097156611"}}
[task 2020-11-02T23:41:57.137Z] PID 352 | 1604360517136	RemoteAgent	TRACE	<-(connection {412c5d14-de93-459d-b253-a67433f172e7}) {"sessionId":"a9180294-d34b-4bc5-aa86-501d0beca82c","id":1196,"result":{"result":{"objectId":"feabfdfa-0253-49e5-8c62-29ba1e9d082d","type":"object","subtype":"node","className":"HTMLIFrameElement","description":"iframe#frame3"}}}
[task 2020-11-02T23:41:57.138Z] PID 352 | 1604360517138	RemoteAgent	TRACE	<-(connection {412c5d14-de93-459d-b253-a67433f172e7}) {"sessionId":"a9180294-d34b-4bc5-aa86-501d0beca82c","id":1197,"result":{"node":{"nodeId":"907ae7c7-2231-458f-a6ab-36ee746d369 ... Value":"","childNodeCount":0,"attributes":["src","http://localhost:8907/empty.html","id","frame1"],"frameId":"45097156609"}}}
[task 2020-11-02T23:41:57.138Z] PID 352 | 1604360517138	RemoteAgent	TRACE	<-(connection {412c5d14-de93-459d-b253-a67433f172e7}) {"sessionId":"a9180294-d34b-4bc5-aa86-501d0beca82c","id":1198,"result":{"node":{"nodeId":"20360929-c7de-4228-b656-ae2a61a830e ... Value":"","childNodeCount":0,"attributes":["src","http://localhost:8907/empty.html","id","frame2"],"frameId":"45097156610"}}}
[task 2020-11-02T23:41:57.168Z] PID 352 | 1604360517168	RemoteAgent	TRACE	(connection {412c5d14-de93-459d-b253-a67433f172e7})-> {"sessionId":"a9180294-d34b-4bc5-aa86-501d0beca82c","method":"DOM.describeNode","params":{"objectId":"feabfdfa-0253-49e5-8c62-29ba1e9d082d"},"id":1199}
[task 2020-11-02T23:41:57.169Z] PID 352 | 1604360517169	RemoteAgent	TRACE	<-(connection {412c5d14-de93-459d-b253-a67433f172e7}) {"sessionId":"a9180294-d34b-4bc5-aa86-501d0beca82c","id":1199,"result":{"node":{"nodeId":"177cb640-01c5-4536-9ebe-9b7a8e71b3f ... Value":"","childNodeCount":0,"attributes":["src","http://localhost:8907/empty.html","id","frame3"],"frameId":"45097156611"}}}
[task 2020-11-02T23:41:57.170Z] PID 352 | 1604360517170	RemoteAgent	TRACE	(connection {412c5d14-de93-459d-b253-a67433f172e7})-> {"sessionId":"a9180294-d34b-4bc5-aa86-501d0beca82c","method":"Page.navigate","params":{"url":"http://localhost:8907/one-style.html","frameId":"45097156609"},"id":1200}
[task 2020-11-02T23:41:57.170Z] PID 352 | 1604360517170	RemoteAgent	ERROR	UnsupportedError: frameId not supported:
[task 2020-11-02T23:41:57.171Z] PID 352 | 	RemoteAgentError@chrome://remote/content/Error.jsm:25:5
[task 2020-11-02T23:41:57.171Z] PID 352 | 	UnsupportedError@chrome://remote/content/Error.jsm:102:1
[task 2020-11-02T23:41:57.171Z] PID 352 | 	navigate@chrome://remote/content/domains/parent/Page.jsm:117:13
[task 2020-11-02T23:41:57.171Z] PID 352 | 	execute@chrome://remote/content/domains/DomainCache.jsm:99:25
[task 2020-11-02T23:41:57.171Z] PID 352 | 	execute@chrome://remote/content/sessions/Session.jsm:64:25
[task 2020-11-02T23:41:57.171Z] PID 352 | 	execute@chrome://remote/content/sessions/TabSession.jsm:67:20
[task 2020-11-02T23:41:57.171Z] PID 352 | 	onPacket@chrome://remote/content/Connection.jsm:225:36
[task 2020-11-02T23:41:57.171Z] PID 352 | 	onMessage@chrome://remote/content/server/WebSocketTransport.jsm:85:18
[task 2020-11-02T23:41:57.171Z] PID 352 | 	handleEvent@chrome://remote/content/server/WebSocketTransport.jsm:67:14
[task 2020-11-02T23:41:57.171Z] PID 352 | caused by:
[task 2020-11-02T23:41:57.171Z] PID 352 | 1604360517170	RemoteAgent	TRACE	<-(connection {412c5d14-de93-459d-b253-a67433f172e7}) {"id":1200,"sessionId":"a9180294-d34b-4bc5-aa86-501d0beca82c","error":{"message":"frameId not supported","data":"RemoteAgentE ... ote/content/server/WebSocketTransport.jsm:85:18\nhandleEvent@chrome://remote/content/server/WebSocketTransport.jsm:67:14\n"}}
[task 2020-11-02T23:42:17.041Z] TEST-UNEXPECTED-TIMEOUT | navigation Frame.goto should return matching responses (navigation.spec.ts) | expected FAIL
[task 2020-11-02T23:42:17.042Z] TEST-INFO expected FAIL | took 20266ms
...
...
[task 2020-11-02T23:45:16.928Z] PID 352 | 1604360716928	RemoteAgent	TRACE	<-(connection {2f4fcff0-67b0-4724-9988-20f492478ab5}) {"sessionId":"8da5d7bd-9211-45b8-b32c-53546d6c5d62","id":112,"result":{"layoutViewport":{"pageX":0,"pageY":0,"clientWidth":800,"clientHeight":600},"contentSize":{"x":0,"y":0,"width":800,"height":35}}}
[task 2020-11-02T23:45:16.968Z] PID 352 | 1604360716968	RemoteAgent	TRACE	(connection {2f4fcff0-67b0-4724-9988-20f492478ab5})-> {"sessionId":"8da5d7bd-9211-45b8-b32c-53546d6c5d62","method":"Input.dispatchMouseEvent","params":{"type":"mouseMoved","button":"none","x":400,"y":17.5,"modifiers":0},"id":113}
[task 2020-11-02T23:45:16.975Z] PID 352 | 1604360716975	RemoteAgent	TRACE	<-(connection {2f4fcff0-67b0-4724-9988-20f492478ab5}) {"sessionId":"8da5d7bd-9211-45b8-b32c-53546d6c5d62","id":113}
[task 2020-11-02T23:45:16.976Z] PID 352 | 1604360716976	RemoteAgent	TRACE	(connection {2f4fcff0-67b0-4724-9988-20f492478ab5})-> {"sessionId":"8da5d7bd-9211-45b8-b32c-53546d6c5d62","method":"Input.dispatchMouseEvent","params":{"type":"mousePressed","button":"left","x":400,"y":17.5,"modifiers":0,"clickCount":1},"id":114}
[task 2020-11-02T23:45:16.977Z] PID 352 | 1604360716976	RemoteAgent	TRACE	<-(connection {2f4fcff0-67b0-4724-9988-20f492478ab5}) {"sessionId":"8da5d7bd-9211-45b8-b32c-53546d6c5d62","id":114}
[task 2020-11-02T23:45:16.977Z] PID 352 | 1604360716977	RemoteAgent	TRACE	(connection {2f4fcff0-67b0-4724-9988-20f492478ab5})-> {"sessionId":"8da5d7bd-9211-45b8-b32c-53546d6c5d62","method":"Input.dispatchMouseEvent","params":{"type":"mouseReleased","button":"left","x":400,"y":17.5,"modifiers":0,"clickCount":1},"id":115}
[task 2020-11-02T23:45:16.977Z] PID 352 | 1604360716977	RemoteAgent	TRACE	<-(connection {2f4fcff0-67b0-4724-9988-20f492478ab5}) {"sessionId":"8da5d7bd-9211-45b8-b32c-53546d6c5d62","id":115}
[task 2020-11-02T23:45:17.012Z] PID 352 | 1604360717012	RemoteAgent	TRACE	(connection {2f4fcff0-67b0-4724-9988-20f492478ab5})-> {"sessionId":"8da5d7bd-9211-45b8-b32c-53546d6c5d62","method":"Runtime.releaseObject","params":{"objectId":"0907629e-ff0e-40c0-bfe7-8fbca5f5eaad"},"id":116}
[task 2020-11-02T23:45:17.013Z] PID 352 | 1604360717013	RemoteAgent	TRACE	<-(connection {2f4fcff0-67b0-4724-9988-20f492478ab5}) {"sessionId":"8da5d7bd-9211-45b8-b32c-53546d6c5d62","id":116}
[task 2020-11-02T23:45:17.014Z] PID 352 | 1604360717014	RemoteAgent	TRACE	(connection {2f4fcff0-67b0-4724-9988-20f492478ab5})-> {"sessionId":"8da5d7bd-9211-45b8-b32c-53546d6c5d62","method":"Page.close","params":{},"id":117}
[task 2020-11-02T23:45:17.015Z] PID 352 | 1604360717015	RemoteAgent	ERROR	UnknownMethodError: Page.close:
[task 2020-11-02T23:45:17.016Z] PID 352 | 	RemoteAgentError@chrome://remote/content/Error.jsm:25:5
[task 2020-11-02T23:45:17.016Z] PID 352 | 	UnknownMethodError@chrome://remote/content/Error.jsm:108:7
[task 2020-11-02T23:45:17.016Z] PID 352 | 	execute@chrome://remote/content/domains/DomainCache.jsm:96:13
[task 2020-11-02T23:45:17.017Z] PID 352 | 	receiveMessage@chrome://remote/content/sessions/ContentProcessSession.jsm:86:45
[task 2020-11-02T23:45:17.017Z] PID 352 | caused by:
[task 2020-11-02T23:45:17.017Z] PID 352 | 1604360717015	RemoteAgent	TRACE	<-(connection {2f4fcff0-67b0-4724-9988-20f492478ab5}) {"id":117,"sessionId":"8da5d7bd-9211-45b8-b32c-53546d6c5d62","error":{"message":"Page.close","data":"RemoteAgentError@chrome: ... e/content/domains/DomainCache.jsm:96:13\nreceiveMessage@chrome://remote/content/sessions/ContentProcessSession.jsm:86:45\n"}}
[task 2020-11-02T23:45:17.017Z] PID 352 | 1604360717016	RemoteAgent	TRACE	<-(connection {2f4fcff0-67b0-4724-9988-20f492478ab5}) {"sessionId":"8da5d7bd-9211-45b8-b32c-53546d6c5d62","method":"Log.entryAdded","params":{"entry":{"source":"javascript","level ... r","text":"Page.close","timestamp":1604360717015,"url":"chrome://remote/content/Error.jsm","lineNumber":25,"stackTrace":{}}}}
[task 2020-11-02T23:45:32.611Z] PID 352 | console.error: BroadcastService:
[task 2020-11-02T23:45:32.611Z] PID 352 |   receivedBroadcastMessage: handler for
[task 2020-11-02T23:45:32.611Z] PID 352 |   remote-settings/monitor_changes
[task 2020-11-02T23:45:32.611Z] PID 352 |   threw error:
[task 2020-11-02T23:45:32.611Z] PID 352 |   Message: Error: Polling for changes failed: NetworkError when attempting to fetch resource..
[task 2020-11-02T23:45:32.611Z] PID 352 |   Stack:
[task 2020-11-02T23:45:32.611Z] PID 352 |     remoteSettingsFunction/remoteSettings.pollChanges@resource://services-settings/remote-settings.js:254:13
[task 2020-11-02T23:45:32.612Z] PID 352 | 
[task 2020-11-02T23:45:36.608Z] TEST-UNEXPECTED-TIMEOUT | Page Page.close should run beforeunload if asked for (page.spec.ts) | expected FAIL
[task 2020-11-02T23:45:36.608Z] TEST-INFO expected FAIL | took 20247ms
[task 2020-11-02T23:45:36.609Z] PID 352 | ["fail",{"title":"should run beforeunload if asked for","fullTitle":"Page Page.close should run beforeunload if asked for","file":"/builds/worker/checkouts/gecko/remote/test/puppeteer/test/page.spec.ts","duration":20004,"currentRetry":0,"err":"Timeout of 20000ms exceeded. For async tests and hooks, ensure \"done()\" is called; if returning a Promise, ensure it resolves. (/builds/worker/checkouts/gecko/remote/test/puppeteer/test/page.spec.ts)","stack":"Error: Timeout of 20000ms exceeded. For async tests and hooks, ensure \"done()\" is called; if returning a Promise, ensure it resolves. (/builds/worker/checkouts/gecko/remote/test/puppeteer/test/page.spec.ts)\n    at Test.Runnable._timeoutError (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runnable.js:432:10)\n    at Timeout.<anonymous> (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runnable.js:244:24)\n    at ontimeout (timers.js:436:11)\n    at tryOnTimeout (timers.js:300:5)\n    at listOnTimeout (timers.js:263:5)\n    at Timer.processTimers (timers.js:223:10)"}]
[task 2020-11-02T23:45:36.609Z] PID 352 | 1604360736609	RemoteAgent	TRACE	(connection {2f4fcff0-67b0-4724-9988-20f492478ab5})-> {"method":"Target.disposeBrowserContext","params":{"browserContextId":8},"id":118}
[task 2020-11-02T23:45:36.624Z] PID 352 | 1604360736624	RemoteAgent	TRACE	<-(connection {2f4fcff0-67b0-4724-9988-20f492478ab5}) {"sessionId":"8da5d7bd-9211-45b8-b32c-53546d6c5d62","method":"Page.javascriptDialogOpening","params":{"message":"This page is asking you to confirm that you want to leave - data you have entered may not be saved.","type":"beforeunload"}}
[task 2020-11-02T23:45:36.626Z] PID 352 | JavaScript error: chrome://remote/content/domains/parent/page/DialogHandler.jsm, line 103: TypeError: can't access property "listPrompts", this._browser.tabModalPromptBox is undefined
[task 2020-11-02T23:45:36.626Z] PID 352 | JavaScript error: chrome://remote/content/domains/parent/page/DialogHandler.jsm, line 103: TypeError: can't access property "listPrompts", this._browser.tabModalPromptBox is undefined
[task 2020-11-02T23:45:36.626Z] PID 352 | JavaScript error: chrome://remote/content/domains/parent/page/DialogHandler.jsm, line 103: TypeError: can't access property "listPrompts", this._browser.tabModalPromptBox is undefined
[task 2020-11-02T23:45:36.627Z] PID 352 | JavaScript error: chrome://remote/content/domains/parent/page/DialogHandler.jsm, line 103: TypeError: can't access property "listPrompts", this._browser.tabModalPromptBox is undefined
[task 2020-11-02T23:45:36.627Z] PID 352 | JavaScript error: chrome://remote/content/domains/parent/page/DialogHandler.jsm, line 103: TypeError: can't access property "listPrompts", this._browser.tabModalPromptBox is undefined
[task 2020-11-02T23:45:36.627Z] PID 352 | JavaScript error: chrome://remote/content/domains/parent/page/DialogHandler.jsm, line 103: TypeError: can't access property "listPrompts", this._browser.tabModalPromptBox is undefined
[task 2020-11-02T23:45:36.627Z] PID 352 | 1604360736626	RemoteAgent	TRACE	(connection {2f4fcff0-67b0-4724-9988-20f492478ab5})-> {"sessionId":"8da5d7bd-9211-45b8-b32c-53546d6c5d62","method":"Page.handleJavaScriptDialog","params":{"accept":true},"id":119}
[task 2020-11-02T23:45:36.628Z] PID 352 | 1604360736627	RemoteAgent	TRACE	<-(connection {2f4fcff0-67b0-4724-9988-20f492478ab5}) {"sessionId":"8da5d7bd-9211-45b8-b32c-53546d6c5d62","id":119}
[task 2020-11-02T23:45:36.637Z] PID 352 | 1604360736637	RemoteAgent	TRACE	<-(connection {2f4fcff0-67b0-4724-9988-20f492478ab5}) {"method":"Target.targetDestroyed","params":{"targetId":"08f9f7af-a759-401a-b767-2f19561a79a0"}}
[task 2020-11-02T23:45:36.638Z] PID 352 | (node:373) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 26)
[task 2020-11-02T23:45:36.642Z] PID 352 | 1604360736642	RemoteAgent	TRACE	<-(connection {2f4fcff0-67b0-4724-9988-20f492478ab5}) {"method":"Target.targetDestroyed","params":{"targetId":"3d21946d-3253-47b8-9f4e-c1d1861756a3"}}
[task 2020-11-02T23:45:36.649Z] PID 352 | 1604360736646	RemoteAgent	TRACE	<-(connection {2f4fcff0-67b0-4724-9988-20f492478ab5}) {"id":118}

Comment 1

[Bogdan Tara[:bogdan_tara | bogdant]]

This showed up on both autoland and central about the same time.

Whimboo, could you, please, take a look?

Comment 2

[Intermittent Failures Robot]

44 failures in 666 pushes (0.066 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 43
• mozilla-central: 1

Platform breakdown:

• linux1804-64: 44

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

Comment 3

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

The failure is reproducible for even older builds that were formerly passing:

https://treeherder.mozilla.org/jobs?repo=autoland&searchStr=pup&tochange=eff49d0860383774c77597474635bab68e5d4a9d&fromchange=24aaf5d4c68bccf698870752ca00e2c8952032f8

I actually cannot see an overall change to the node.js packages as installed, but maybe one package upgraded without affected any dependencies?

Maybe we should indeed start to pin the packages.

Maja, could you have a look at these failures? Maybe we just do an expectation update again?

Comment 4

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

I had a quick look given that Maja isn't around today, and I feel that the test itself actually aborts early with the UnsupportedError but then maybe the teardown code somewhat hangs and producing the timeout?

Comment 5

[Intermittent Failures Robot]

120 failures in 801 pushes (0.15 failures/push) were associated with this bug yesterday.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• autoland: 116
• mozilla-central: 4

Platform breakdown:

• linux1804-64: 120

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

Comment 6

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

Attachment: Bug 1674939 - [puppeteer] Update metadata for Page.close and Frame.goto tests

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/1d6d547af669
[puppeteer] Update metadata for Page.close and Frame.goto tests r=remote-protocol-reviewers,whimboo

Comment 8

[Cristian Brindusan [:cbrindusan]]

https://hg.mozilla.org/mozilla-central/rev/1d6d547af669

Comment 9

[Intermittent Failures Robot]

42 failures in 747 pushes (0.056 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 38
• mozilla-central: 2
• try: 2

Platform breakdown:

• linux1804-64: 42

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

Comment 10

[Cosmin Sabou [:CosminS]]

No failures since the patch landed.

Comment 11

[Intermittent Failures Robot]

211 failures in 4128 pushes (0.051 failures/push) were associated with this bug in the last 7 days.

This is the #2 most frequent failure this week.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• autoland: 200
• mozilla-central: 7
• try: 4

Platform breakdown:

• linux1804-64: 211

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

Comment 12

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 4

Platform breakdown:

• linux1804-64: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1674939&startday=2020-11-09&endday=2020-11-15&tree=all