Closed Bug 1671725 Opened 4 years ago Closed 4 years ago

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

Categories

(Remote Protocol :: Agent, defect, P5)

defect

Tracking

(firefox84 fixed)

RESOLVED FIXED
84 Branch
Tracking Status
firefox84 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [stockwell disable-recommended])

Attachments

(5 files)

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}```
Component: Browser → Agent

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.

Flags: needinfo?(ksteuber)

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)
Flags: needinfo?(hskupin)

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

Flags: needinfo?(hskupin) → needinfo?(mjzffr)

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

Flags: needinfo?(mjzffr)

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

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

Assignee: nobody → mjzffr
Status: NEW → ASSIGNED

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

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?

Flags: needinfo?(jmaher)

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.

Flags: needinfo?(jmaher)

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

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.

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>}]

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

Depends on D94361

Pushed by mjzffr@gmail.com: 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

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

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: