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)
Tracking
(firefox84 fixed)
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}```
Comment 1•4 years ago
|
||
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
Updated•4 years ago
|
Comment 2•4 years ago
|
||
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•4 years ago
|
||
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 hidden (Intermittent Failures Robot) |
Comment 5•4 years ago
|
||
I'm away and will be back on Wednesday. Maja, can you please have a look?
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 7•4 years ago
|
||
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
Assignee | ||
Comment 8•4 years ago
|
||
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 hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 10•4 years ago
|
||
This prevents the errors from being raised later on during an unrelated
test.
Updated•4 years ago
|
Assignee | ||
Comment 11•4 years ago
|
||
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 hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 13•4 years ago
|
||
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•4 years ago
|
||
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•4 years ago
|
||
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
Assignee | ||
Comment 16•4 years ago
|
||
Ah, good eye. Filed https://bugzilla.mozilla.org/show_bug.cgi?id=1672461
Assignee | ||
Comment 17•4 years ago
|
||
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.
Assignee | ||
Comment 18•4 years ago
|
||
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>}]
Assignee | ||
Comment 19•4 years ago
|
||
Depends on D94245
Assignee | ||
Comment 20•4 years ago
|
||
This prevents intermittent orange jobs where an additional test result is
counted after the test has already ended.
Depends on D94361
Comment hidden (Intermittent Failures Robot) |
Comment 22•4 years ago
|
||
Comment 23•4 years ago
|
||
bugherder |
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 hidden (Intermittent Failures Robot) |
Comment 25•4 years ago
|
||
Thanks a lot Maja for fixing this perma failure. Good to see the pup job being green again.
Comment hidden (Intermittent Failures Robot) |
Description
•