1671725 - Perma puppeteer TEST-UNEXPECTED-ERROR Cookie specs "before each" hook for "should return no cookies in pristine browser context" (cookies.spec.ts)

Status: RESOLVED FIXED

(Remote Protocol :: Agent, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-10-16T21:26:49.007Z] TEST-START | Cookie specs Page.cookies should return no cookies in pristine browser context (cookies.spec.ts)
[task 2020-10-16T21:26:49.007Z] PID 347 | ["test-start",{"title":"should return no cookies in pristine browser context","fullTitle":"Cookie specs Page.cookies should return no cookies in pristine browser context","file":"/builds/worker/checkouts/gecko/remote/test/puppeteer/test/cookies.spec.ts","currentRetry":0}]
[task 2020-10-16T21:26:49.007Z] PID 347 | 1602883609007	RemoteAgent	TRACE	(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad})-> {"method":"Target.createBrowserContext","id":2}
[task 2020-10-16T21:26:49.008Z] PID 347 | 1602883609007	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"id":2,"result":{"browserContextId":6}}
[task 2020-10-16T21:26:49.009Z] PID 347 | 1602883609009	RemoteAgent	TRACE	(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad})-> {"method":"Target.createTarget","params":{"url":"about:blank","browserContextId":6},"id":3}
[task 2020-10-16T21:26:49.024Z] PID 347 | 1602883609023	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"method":"Target.targetCreated","params":{"targetInfo":{"browserContextId":6,"targetId":"d3bab2e9-23a8-4b20-8702-34ff11c0af28","type":"page","url":"about:blank"}}}
[task 2020-10-16T21:26:49.043Z] PID 347 | 1602883609043	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"id":3,"result":{"targetId":"d3bab2e9-23a8-4b20-8702-34ff11c0af28"}}
[task 2020-10-16T21:26:49.076Z] PID 347 | 1602883609076	RemoteAgent	TRACE	(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad})-> {"method":"Target.attachToTarget","params":{"targetId":"d3bab2e9-23a8-4b20-8702-34ff11c0af28","flatten":true},"id":4}
[task 2020-10-16T21:26:49.076Z] PID 347 | 1602883609076	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"method":"Target.attachedToTarget","params":{"targetInfo":{"type":"page"},"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d"}}
[task 2020-10-16T21:26:49.077Z] PID 347 | 1602883609076	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"id":4,"result":{"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d"}}
[task 2020-10-16T21:26:49.115Z] PID 347 | 1602883609115	RemoteAgent	TRACE	(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad})-> {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","method":"Page.enable","params":{},"id":5}
[task 2020-10-16T21:26:49.120Z] PID 347 | 1602883609120	RemoteAgent	TRACE	(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad})-> {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","method":"Page.getFrameTree","params":{},"id":6}
[task 2020-10-16T21:26:49.121Z] PID 347 | 1602883609120	RemoteAgent	TRACE	(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad})-> {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","method":"Target.setAutoAttach","params":{"autoAttach":true,"waitForDebuggerOnStart":false,"flatten":true},"id":7}
[task 2020-10-16T21:26:49.121Z] PID 347 | 1602883609120	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","id":7}
[task 2020-10-16T21:26:49.121Z] PID 347 | 1602883609120	RemoteAgent	TRACE	(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad})-> {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","method":"Performance.enable","params":{},"id":8}
[task 2020-10-16T21:26:49.121Z] PID 347 | 1602883609120	RemoteAgent	TRACE	(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad})-> {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","method":"Log.enable","params":{},"id":9}
[task 2020-10-16T21:26:49.123Z] PID 347 | 1602883609122	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","id":5}
[task 2020-10-16T21:26:49.123Z] PID 347 | 1602883609122	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","id":6,"result":{"frameTree":{"frame":{"id":"34","url":"about:blank","securityOrigin":null,"mimeType":null}}}}
[task 2020-10-16T21:26:49.123Z] PID 347 | 1602883609122	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","id":8}
[task 2020-10-16T21:26:49.123Z] PID 347 | 1602883609123	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","id":9}
[task 2020-10-16T21:26:49.158Z] PID 347 | 1602883609158	RemoteAgent	TRACE	(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad})-> {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","method":"Page.setLifecycleEventsEnabled","params":{"enabled":true},"id":10}
[task 2020-10-16T21:26:49.159Z] PID 347 | 1602883609158	RemoteAgent	TRACE	(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad})-> {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","method":"Runtime.enable","params":{},"id":11}
[task 2020-10-16T21:26:49.159Z] PID 347 | 1602883609159	RemoteAgent	TRACE	(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad})-> {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","method":"Network.enable","params":{},"id":12}
[task 2020-10-16T21:26:49.161Z] PID 347 | 1602883609161	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","id":12}
[task 2020-10-16T21:26:49.162Z] PID 347 | 1602883609161	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","id":10}
[task 2020-10-16T21:26:49.163Z] PID 347 | 1602883609162	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","id":11}
[task 2020-10-16T21:26:49.163Z] PID 347 | 1602883609163	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","method":"Runtime.executionContextCreated","params":{"context":{"id":1,"origin":"about:blank","name":"","auxData":{"isDefault":true,"frameId":"34","type":"default"}}}}
[task 2020-10-16T21:26:49.199Z] PID 347 | 1602883609198	RemoteAgent	TRACE	(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad})-> {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","method":"Page.addScriptToEvaluateOnNewDocument","params":{"source":"//# sourceURL=__puppeteer_evaluation_script__","worldName":"__puppeteer_utility_world__"},"id":13}
[task 2020-10-16T21:26:49.200Z] PID 347 | 1602883609200	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","id":13,"result":{"identifier":"608601fa-8dad-4309-99b3-65770a04fde5"}}
[task 2020-10-16T21:26:49.201Z] PID 347 | 1602883609201	RemoteAgent	TRACE	(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad})-> {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","method":"Page.createIsolatedWorld","params":{"frameId":"34","grantUniveralAccess":true,"worldName":"__puppeteer_utility_world__"},"id":14}
[task 2020-10-16T21:26:49.202Z] PID 347 | 1602883609201	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","method":"Runtime.executionContextCreated","params":{"context":{"id":2,"origin":"about:blank","name":"__puppeteer_utility_world__","auxData":{"isDefault":false,"frameId":"34","type":"isolated"}}}}
[task 2020-10-16T21:26:49.202Z] PID 347 | 1602883609202	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","id":14,"result":{"executionContextId":2}}
[task 2020-10-16T21:26:49.234Z] TEST-UNEXPECTED-ERROR Cookie specs "before each" hook for "should return no cookies in pristine browser context" (cookies.spec.ts)
[task 2020-10-16T21:26:49.234Z] PID 347 | ["fail",{"title":"\"before each\" hook for \"should return no cookies in pristine browser context\"","fullTitle":"Cookie specs \"before each\" hook for \"should return no cookies in pristine browser context\"","file":"/builds/worker/checkouts/gecko/remote/test/puppeteer/test/cookies.spec.ts","duration":227,"currentRetry":0,"err":"waiting for target failed: timeout 30000ms exceeded","stack":"TimeoutError: waiting for target failed: timeout 30000ms exceeded\n    at Object.waitWithTimeout (/builds/worker/checkouts/gecko/remote/test/puppeteer/src/common/helper.ts:228:24)\n    at Browser.waitForTarget (/builds/worker/checkouts/gecko/remote/test/puppeteer/src/common/Browser.ts:368:27)\n    at Browser.<anonymous> (/builds/worker/checkouts/gecko/remote/test/puppeteer/src/common/helper.ts:114:21)\n    at BrowserContext.waitForTarget (/builds/worker/checkouts/gecko/remote/test/puppeteer/src/common/Browser.ts:526:26)\n    at Context.it (/builds/worker/checkouts/gecko/remote/test/puppeteer/test/browsercontext.spec.ts:103:35)\n    at process._tickCallback (internal/process/next_tick.js:68:7)"}]
[task 2020-10-16T21:26:49.235Z] PID 347 | 1602883609234	RemoteAgent	TRACE	(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad})-> {"method":"Target.disposeBrowserContext","params":{"browserContextId":6},"id":15}
[task 2020-10-16T21:26:49.253Z] PID 347 | 1602883609252	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"method":"Target.targetDestroyed","params":{"targetId":"d3bab2e9-23a8-4b20-8702-34ff11c0af28"}}
[task 2020-10-16T21:26:49.255Z] PID 347 | 1602883609255	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"id":15}
[task 2020-10-16T21:26:49.264Z] PID 347 | 1602883609263	RemoteAgent	TRACE	(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad})-> {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","method":"Emulation.setDeviceMetricsOverride","params":{"mobile":false,"width":800,"height":600,"deviceScaleFactor":1,"screenOrientation":{"angle":0,"type":"portraitPrimary"}},"id":16}
[task 2020-10-16T21:26:49.264Z] PID 347 | 1602883609264	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"id":16,"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","error":{"message":"tab is undefined","data":"setDeviceMetricsOve ... ote/content/server/WebSocketTransport.jsm:85:18\nhandleEvent@chrome://remote/content/server/WebSocketTransport.jsm:67:14\n"}}
[task 2020-10-16T21:26:49.265Z] PID 347 | 1602883609264	RemoteAgent	TRACE	(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad})-> {"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","method":"Emulation.setTouchEmulationEnabled","params":{"enabled":false},"id":17}
[task 2020-10-16T21:26:49.266Z] PID 347 | 1602883609264	RemoteAgent	TRACE	<-(connection {c425559a-80cc-4137-a82e-4bb4c70ac0ad}) {"id":17,"sessionId":"7f53d111-e69c-4453-8f43-9b2c63e7df4d","error":{"message":"can't access property \"sendAsyncMessage\", t ... ote/content/server/WebSocketTransport.jsm:85:18\nhandleEvent@chrome://remote/content/server/WebSocketTransport.jsm:67:14\n"}}
[task 2020-10-16T21:26:49.292Z] TEST-UNEXPECTED-ERROR Cookie specs "before each" hook for "should return no cookies in pristine browser context" (cookies.spec.ts)
[task 2020-10-16T21:26:49.293Z] PID 347 | ["fail",{"title":"\"before each\" hook for \"should return no cookies in pristine browser context\"","fullTitle":"Cookie specs \"before each\" hook for \"should return no cookies in pristine browser context\"","file":"/builds/worker/checkouts/gecko/remote/test/puppeteer/test/cookies.spec.ts","duration":227,"currentRetry":0,"err":"done() called multiple times in hook <Cookie specs \"before each\" hook for \"should return no cookies in pristine browser context\"> of file /builds/worker/checkouts/gecko/remote/test/puppeteer/test/cookies.spec.ts; in addition, done() received error: Error: Protocol error (Emulation.setDeviceMetricsOverride): tab is undefined setDeviceMetricsOverride@chrome://remote/content/domains/parent/Emulation.jsm:70:40\nexecute@chrome://remote/content/domains/DomainCache.jsm:99:25\nexecute@chrome://remote/content/sessions/Session.jsm:64:25\nexecute@chrome://remote/content/sessions/TabSession.jsm:67:20\nonPacket@chrome://remote/content/Connection.jsm:225:36\nonMessage@chrome://remote/content/server/WebSocketTransport.jsm:85:18\nhandleEvent@chrome://remote/content/server/WebSocketTransport.jsm:67:14\n","stack":"Error: done() called multiple times in hook <Cookie specs \"before each\" hook for \"should return no cookies in pristine browser context\"> of file /builds/worker/checkouts/gecko/remote/test/puppeteer/test/cookies.spec.ts; in addition, done() received error: Error: Protocol error (Emulation.setDeviceMetricsOverride): tab is undefined setDeviceMetricsOverride@chrome://remote/content/domains/parent/Emulation.jsm:70:40\nexecute@chrome://remote/content/domains/DomainCache.jsm:99:25\nexecute@chrome://remote/content/sessions/Session.jsm:64:25\nexecute@chrome://remote/content/sessions/TabSession.jsm:67:20\nonPacket@chrome://remote/content/Connection.jsm:225:36\nonMessage@chrome://remote/content/server/WebSocketTransport.jsm:85:18\nhandleEvent@chrome://remote/content/server/WebSocketTransport.jsm:67:14\n\n    at createMultipleDoneError (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/errors.js:364:13)\n    at multiple (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runnable.js:288:24)\n    at done (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runnable.js:299:14)\n    at /builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runnable.js:375:11\n    at process._tickCallback (internal/process/next_tick.js:68:7)"}]
[task 2020-10-16T21:26:49.313Z] PID 347 | Exiting due to channel error.
[task 2020-10-16T21:26:49.313Z] PID 347 | Exiting due to channel error.
[task 2020-10-16T21:26:49.315Z] PID 347 | Exiting due to channel error.
[task 2020-10-16T21:26:49.315Z] PID 347 | Exiting due to channel error.
[task 2020-10-16T21:26:49.342Z] PID 347 | *** You are running in headless mode.
[task 2020-10-16T21:26:50.719Z] PID 347 | DevTools listening on ws://localhost:32932/devtools/browser/dea2f82a-69ba-4d2f-a97a-eb24ddd1cee2
[task 2020-10-16T21:26:50.729Z] PID 347 | 1602883610728	RemoteAgent	TRACE	(connection {96660d35-93aa-42db-8f91-b7a3b9341e74})-> {"method":"Target.setDiscoverTargets","params":{"discover":true},"id":1}
[task 2020-10-16T21:26:50.730Z] PID 347 | 1602883610729	RemoteAgent	TRACE	<-(connection {96660d35-93aa-42db-8f91-b7a3b9341e74}) {"method":"Target.targetCreated","params":{"targetInfo":{"browserContextId":null,"targetId":"a0b931da-a209-4a08-99cd-aaf41cfa7b23","type":"page","url":"about:blank"}}}
[task 2020-10-16T21:26:50.730Z] PID 347 | 1602883610729	RemoteAgent	TRACE	<-(connection {96660d35-93aa-42db-8f91-b7a3b9341e74}) {"method":"Target.targetCreated","params":{"targetInfo":{"targetId":"dea2f82a-69ba-4d2f-a97a-eb24ddd1cee2","type":"browser"}}}
[task 2020-10-16T21:26:50.730Z] PID 347 | 1602883610730	RemoteAgent	TRACE	<-(connection {96660d35-93aa-42db-8f91-b7a3b9341e74}) {"id":1}```

Comment 1

[Cosmin Sabou [:CosminS]]

Kirk, please have a look over this perma failure that started after Bug 1647313 landed. Thank you.
https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception&searchStr=pup&tochange=7dbc11b10cb06d65133570a6d14e64e110756f4b&fromchange=ac431d6e63f0fe54b7670e7c072da5352cd35092&selectedTaskRun=PWjpA0AXSi-RnHdOSZ491g.0

Comment 2

[Robin Steuber (she/her) [:bytesized]]

Looking at this test failure, I am extremely confused. I am used to test failures giving a test names and tracebacks. But looking at this test failure, I'm having a pretty tough time making heads or tails of what exactly is failing. It looks like Puppeteer is making some kind of cookie check that's failing?

The patch for Bug 1647313 simply introduces some testing code that was already in some Firefox Application Update tests, and used it in some other Firefox Application Update tests. My patch certainly didn't touch any cookies, so it seems pretty unlikely that it could have produced this error message.

I think a different patch must have caused this.

Comment 3

[Cosmin Sabou [:CosminS]]

Henrik, could you please shed some light here on how these remote-puppeteer tests work and why they started to fail with Kirk's changes? Thank you.

There are several error lines in the log:

3274	TEST-UNEXPECTED-ERROR Cookie specs "before each" hook for "should return no cookies in pristine browser context" (cookies.spec.ts)
3283	TEST-UNEXPECTED-ERROR Cookie specs "before each" hook for "should return no cookies in pristine browser context" (cookies.spec.ts)
21108	TEST-UNEXPECTED-FAIL | navigation Frame.goto should return matching responses (navigation.spec.ts) | expected TIMEOUT
24040	TEST-UNEXPECTED-FAIL | Page Page.close should run beforeunload if asked for (page.spec.ts) | expected TIMEOUT
31639	TEST-UNEXPECTED-ERROR Page "after each" hook in "Page" (page.spec.ts)
40165	TEST-UNEXPECTED-TIMEOUT | waittask specs Frame.waitForSelector Page.waitForSelector is shortcut for main frame (waittask.spec.ts) | expected PASS
41696	TEST-UNEXPECTED-MISSING Cookie specs Page.cookies should get a cookie (cookies.spec.ts)
41697	TEST-UNEXPECTED-MISSING Cookie specs Page.setCookie should set secure same-site cookies from a frame (cookies.spec.ts)
41698	TEST-UNEXPECTED-MISSING Cookie specs Page.cookies should properly report httpOnly cookie (cookies.spec.ts)
41699	TEST-UNEXPECTED-MISSING Cookie specs Page.setCookie should have |expires| set to |-1| for session cookies (cookies.spec.ts)
41700	TEST-UNEXPECTED-MISSING Cookie specs Page.setCookie should be able to set unsecure cookie for HTTP website (cookies.spec.ts)
41701	TEST-UNEXPECTED-MISSING Cookie specs Page.setCookie should not set a cookie on a data URL page (cookies.spec.ts)
41702	TEST-UNEXPECTED-MISSING Cookie specs Page.setCookie should default to setting secure cookie for HTTPS websites (cookies.spec.ts)
41703	TEST-UNEXPECTED-MISSING Cookie specs Page.deleteCookie should work (cookies.spec.ts)
41704	TEST-UNEXPECTED-MISSING Cookie specs Page.setCookie should set multiple cookies (cookies.spec.ts)
41705	TEST-UNEXPECTED-MISSING Cookie specs Page.cookies should properly report "Strict" sameSite cookie (cookies.spec.ts)
41706	TEST-UNEXPECTED-MISSING Cookie specs Page.setCookie should not set a cookie with blank page URL (cookies.spec.ts)
41707	TEST-UNEXPECTED-MISSING Cookie specs Page.cookies should get multiple cookies (cookies.spec.ts)
41708	TEST-UNEXPECTED-MISSING Cookie specs Page.setCookie should set cookies from a frame (cookies.spec.ts)
41709	TEST-UNEXPECTED-MISSING Cookie specs Page.cookies should return no cookies in pristine browser context (cookies.spec.ts)
41710	TEST-UNEXPECTED-MISSING Cookie specs Page.cookies should properly report "Lax" sameSite cookie (cookies.spec.ts)
41711	TEST-UNEXPECTED-MISSING Cookie specs Page.setCookie should set a cookie with a path (cookies.spec.ts)
41712	TEST-UNEXPECTED-MISSING Cookie specs Page.setCookie should set a cookie on a different domain (cookies.spec.ts)
41713	TEST-UNEXPECTED-MISSING Cookie specs Page.setCookie should not set a cookie on a blank page (cookies.spec.ts)
41714	TEST-UNEXPECTED-MISSING Cookie specs Page.cookies should get cookies from multiple urls (cookies.spec.ts)
41715	TEST-UNEXPECTED-MISSING Cookie specs Page.setCookie should isolate cookies in browser contexts (cookies.spec.ts)
41716	TEST-UNEXPECTED-MISSING Cookie specs Page.setCookie should set cookie with reasonable defaults (cookies.spec.ts)
41717	TEST-UNEXPECTED-MISSING Cookie specs Page.setCookie should work (cookies.spec.ts)

Comment 4

[Intermittent Failures Robot]

20 failures in 655 pushes (0.031 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 19
• mozilla-central: 1

Platform breakdown:

• linux1804-64: 20

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

Comment 5

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

I'm away and will be back on Wednesday. Maja, can you please have a look?

Comment 6

[Intermittent Failures Robot]

39 failures in 3694 pushes (0.011 failures/push) were associated with this bug in the last 7 days.

This is the #35 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 34
• mozilla-central: 5

Platform breakdown:

• linux1804-64: 39

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

Comment 7

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

The error stack refers to browsercontext.spec.ts:103:35 where the test starts an async operation to get a CDP target about 30 seconds before we see the cookie-related failures.

[task 2020-10-16T21:26:49.234Z] PID 347 | ["fail",{"title":"\"before each\" hook for \"should return no cookies in pristine browser 
context\"","fullTitle":"Cookie specs \"before each\" hook for \"should return no cookies in pristine browser context\"","file":"/builds
/worker/checkouts/gecko/remote/test/puppeteer/test/cookies.spec.ts","duration":227,"currentRetry":0,"err":"waiting for target failed: timeout 30000ms exceeded",
"stack":"TimeoutError: waiting for target failed: timeout 30000ms exceeded
   at Object.waitWithTimeout (/builds/worker/checkouts/gecko/remote/test/puppeteer/src/common/helper.ts:228:24)
    at Browser.waitForTarget (/builds/worker/checkouts/gecko/remote/test/puppeteer/src/common/Browser.ts:368:27)
    at Browser.<anonymous> (/builds/worker/checkouts/gecko/remote/test/puppeteer/src/common/helper.ts:114:21)
    at BrowserContext.waitForTarget (/builds/worker/checkouts/gecko/remote/test/puppeteer/src/common/Browser.ts:526:26)
    at Context.it (/builds/worker/checkouts/gecko/remote/test/puppeteer/test/browsercontext.spec.ts:103:35)
    at process._tickCallback (internal/process/next_tick.js:68:7)"}]

This looks like a timing issue related to this unhandled promise rejection. The unhandled rejection has always been there, but now it's interfering with the call to puppeteer.launch and/or browser.close() in later test setup/teardown.

Perhaps we haven't hit it before because cumulative test duration was different, e.g. maybe browser start-up/shutdown has changed in duration. I can't reproduce it on my local Ubuntu, so it's CI specific, but I don't see any recent changes in the docker image.

Here's a try push where the promise rejection is handled in the test. Let's see if it helps.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=84c054dcdc2c6a67cec1d04ad43471330042c712

Comment 8

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

Dealing with that particular promise rejection helped, but there are many others like it so the pup job still fails.

I'll see if there's a more general solution that can be applied to the harness overall.

In the meantime, maybe mocha's early cutoff of these async operations makes the error handling uglier. Here's a try push with global mocha timeout set to 31s (since other internal puppeteer timeouts seem to be 30s): https://treeherder.mozilla.org/#/jobs?repo=try&revision=c01d0699827ab17e4de80399269be2128e6a03f7

Comment 9

[Intermittent Failures Robot]

74 failures in 590 pushes (0.125 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 72
• mozilla-central: 2

Platform breakdown:

• linux1804-64: 74

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

Comment 10

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

Attachment: Bug 1671725 - [puppeteer] Handle async TimeoutErrors in several tests

This prevents the errors from being raised later on during an unrelated
test.

Comment 11

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

Attachment: Bug 1671725 - [puppeteer] Increase mocha timeout to 20 seconds.

We originally set 15s to keep the overall job duration under 30 minutes.
Since then, we hit timeouts much less frequently and should be able to
afford a longer timeout. The Puppeteer project's default test timeout
is currently 25 seconds.

Also skipping a Page test due to an async Firefox-specific protocol
error that interferes with teardown.

Depends on D94244

Comment 12

[Intermittent Failures Robot]

68 failures in 746 pushes (0.091 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: 66
• mozilla-central: 2

Platform breakdown:

• linux1804-64: 68

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

Comment 13

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

Attachment: Retriggered jobs failing on green autoland pushes.

Henrik had a hunch that we can detect that this is a CI environment issue by retriggering autoland pup jobs that we scheduled before this permafailure was identified. Behold: they are orange.

Joel, any idea what might have changed in the Linux CI environment around October 16th?

Comment 14

[Joel Maher ( :jmaher ) (UTC -8)]

I am not sure, but this morning there was a discussion about perf regressions on linux + windows from Oct 6th - that would be the datacenter.

we couldn't think of anything.

This would be AWS linux docker images ubuntu1804-test; I don't see changes to the dockerfile recently. Last week there were hg fingerprint issues, and that affected all -source machines which I see the puppeteer jobs use a source machine. Either those changes or the deployment/rebuilding with those changes picking up something else is most likely the cause.

Comment 15

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Was there a (major) update of a dependency?
passing log: added 466 packages from 728 contributors and audited 469 packages in 32.291s
failing log: added 427 packages from 720 contributors and audited 431 packages in 21.45s

Comment 16

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

Ah, good eye. Filed https://bugzilla.mozilla.org/show_bug.cgi?id=1672461

Comment 17

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

The attached commit series greens up the pup job in its current state. I noticed one more problem where the mocha log intermittently spits out both a timeout and a test_end for the same test, which trips up the custom log parser and causes it to report an extra unexpected fail. I'll add a fix to this commit stack.

Comment 18

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

An example: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=319259011&repo=try&lineNumber=22819

TEST-FAIL | navigation Frame.goto should return matching responses (navigation.spec.ts) | took 424ms
PID 355 | ["fail",{"title":"should return matching responses","fullTitle":"navigation Frame.goto should return matching responses","file":"/builds/worker/checkouts/gecko/remote/test/puppeteer/test/navigation.spec.ts",<snip>}]
TEST-START | navigation Frame.waitForNavigation should work (navigation.spec.ts)
PID 355 | ["test-start",{"title":"should work","fullTitle":"navigation Frame.waitForNavigation should work","file":"/builds/worker/checkouts/gecko/remote/test/puppeteer/test/navigation.spec.ts","currentRetry":0}]
test_end for navigation Frame.goto should return matching responses (navigation.spec.ts) logged while not in progress. Logged with data: {"status": "FAIL", "known_intermittent": [], "test": "navigation Frame.goto should return matching responses (navigation.spec.ts)"}
PID 355 | ["fail",{"title":"should return matching responses","fullTitle":"navigation Frame.goto should return matching responses","<snip>}]

Comment 19

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

Attachment: Bug 1671725 - [puppeteer] Add missing await.

Depends on D94245

Comment 20

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

Attachment: Bug 1671725 - [puppeteer] Avoid recording second test status after timeout

This prevents intermittent orange jobs where an additional test result is
counted after the test has already ended.

Depends on D94361

Comment 21

[Intermittent Failures Robot]

62 failures in 878 pushes (0.071 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 60
• mozilla-central: 2

Platform breakdown:

• linux1804-64: 62

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

Comment 22

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/c4e1d98be9e9
[puppeteer] Handle async TimeoutErrors in several tests r=remote-protocol-reviewers,whimboo
https://hg.mozilla.org/integration/autoland/rev/ee5e5b7cf326
[puppeteer] Increase mocha timeout to 20 seconds. r=remote-protocol-reviewers,jgraham,whimboo
https://hg.mozilla.org/integration/autoland/rev/1d8edb443d36
[puppeteer] Add missing await. r=remote-protocol-reviewers,whimboo
https://hg.mozilla.org/integration/autoland/rev/8fc22cfd99db
[puppeteer] Avoid recording second test status after timeout r=remote-protocol-reviewers,whimboo

Comment 23

[Noemi Erli[:noemi_erli]]

https://hg.mozilla.org/mozilla-central/rev/c4e1d98be9e9
https://hg.mozilla.org/mozilla-central/rev/ee5e5b7cf326
https://hg.mozilla.org/mozilla-central/rev/1d8edb443d36
https://hg.mozilla.org/mozilla-central/rev/8fc22cfd99db

Comment 24

[Intermittent Failures Robot]

20 failures in 865 pushes (0.023 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 18
• mozilla-central: 2

Platform breakdown:

• linux1804-64: 20

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

Comment 25

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

Thanks a lot Maja for fixing this perma failure. Good to see the pup job being green again.

Comment 26

[Intermittent Failures Robot]

224 failures in 4230 pushes (0.053 failures/push) were associated with this bug in the last 7 days.

This is the #3 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 216
• mozilla-central: 8

Platform breakdown:

• linux1804-64: 224

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