Closed Bug 1773878 Opened 3 years ago Closed 2 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | Touchscreen should tap the button (touchscreen.spec.ts / .js) | expected FAIL

Categories

(Remote Protocol :: Agent, defect, P5)

Product:
Remote Protocol
Component:
Agent
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

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

TEST-START | Touchscreen should tap the button (touchscreen.spec.ts)
[task 2022-06-12T10:10:55.921Z] PID 397 | ["test-start",{"title":"should tap the button","fullTitle":"Touchscreen should tap the button","file":"/builds/worker/checkouts/gecko/remote/test/puppeteer/test/touchscreen.spec.ts","currentRetry":0}]
[task 2022-06-12T10:10:55.922Z] PID 397 | 1655028655921	CDP	TRACE	CDPConnection 6e800ec5-9d0b-47e5-a430-5222788e409e -> {"method":"Target.createBrowserContext","params":{"proxyServer":"","proxyBypassList":""},"id":2}
[task 2022-06-12T10:10:55.922Z] PID 397 | 1655028655922	CDP	TRACE	CDPConnection 6e800ec5-9d0b-47e5-a430-5222788e409e <- {"id":2,"result":{"browserContextId":6}}
[task 2022-06-12T10:10:55.922Z] PID 397 | 1655028655922	CDP	TRACE	CDPConnection 6e800ec5-9d0b-47e5-a430-5222788e409e -> {"method":"Target.createTarget","params":{"url":"about:blank","browserContextId":6},"id":3}
[task 2022-06-12T10:10:55.945Z] PID 397 | 1655028655945	CDP	TRACE	CDPConnection 6e800ec5-9d0b-47e5-a430-5222788e409e <- {"method":"Target.targetCreated","params":{"targetInfo":{"targetId":"83fa3ee4-8093-4801-9e78-65f390cf0e6e","type":"page","title":"","url":"about:blank","attached":false,"browserContextId":6}}}
[task 2022-06-12T10:10:55.972Z] PID 397 | 1655028655971	RemoteAgent	TRACE	Received DOM event TabSelect for [object XULElement]
<...>
1655028656240	CDP	TRACE	CDPConnection 6e800ec5-9d0b-47e5-a430-5222788e409e <- {"method":"Target.receivedMessageFromTarget","params":{"sessionId":"35c9b071-f37f-464b-939b-8bc644763046","message":"{\"method\":\"Page.frameStoppedLoading\",\"params\":{\"frameId\":\"40\"}}"}}
[task 2022-06-12T10:11:04.265Z] PID 397 | TimeoutError: waiting for target failed: timeout 30000ms exceeded
[task 2022-06-12T10:11:04.265Z] PID 397 |     at Object.waitWithTimeout (/builds/worker/checkouts/gecko/remote/test/puppeteer/src/common/helper.ts:300:24)
[task 2022-06-12T10:11:04.266Z] PID 397 |     at Browser.waitForTarget (/builds/worker/checkouts/gecko/remote/test/puppeteer/src/common/Browser.ts:524:27)
[task 2022-06-12T10:11:04.266Z] PID 397 |     at Context.<anonymous> (/builds/worker/checkouts/gecko/remote/test/puppeteer/test/target.spec.ts:258:37)
[task 2022-06-12T10:11:04.266Z] PID 397 |     at callFn (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runnable.js:366:21)
[task 2022-06-12T10:11:04.266Z] PID 397 |     at Test.Runnable.run (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runnable.js:354:5)
[task 2022-06-12T10:11:04.266Z] PID 397 |     at Runner.runTest (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runner.js:681:10)
[task 2022-06-12T10:11:04.266Z] PID 397 |     at /builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runner.js:804:12
[task 2022-06-12T10:11:04.266Z] PID 397 |     at next (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runner.js:596:14)
[task 2022-06-12T10:11:04.266Z] PID 397 |     at /builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runner.js:606:7
[task 2022-06-12T10:11:04.266Z] PID 397 |     at next (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runner.js:489:14)
[task 2022-06-12T10:11:04.266Z] PID 397 |     at Immediate.<anonymous> (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runner.js:574:5)
[task 2022-06-12T10:11:04.266Z] PID 397 |     at processImmediate (internal/timers.js:461:21)
[task 2022-06-12T10:11:04.266Z] PID 397 | TimeoutError: waiting for target failed: timeout 30000ms exceeded
[task 2022-06-12T10:11:04.267Z] PID 397 |     at Object.waitWithTimeout (/builds/worker/checkouts/gecko/remote/test/puppeteer/src/common/helper.ts:300:24)
[task 2022-06-12T10:11:04.267Z] PID 397 |     at Browser.waitForTarget (/builds/worker/checkouts/gecko/remote/test/puppeteer/src/common/Browser.ts:524:27)
[task 2022-06-12T10:11:04.267Z] PID 397 |     at Context.<anonymous> (/builds/worker/checkouts/gecko/remote/test/puppeteer/test/target.spec.ts:258:37)
[task 2022-06-12T10:11:04.267Z] PID 397 |     at callFn (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runnable.js:366:21)
[task 2022-06-12T10:11:04.267Z] PID 397 |     at Test.Runnable.run (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runnable.js:354:5)
[task 2022-06-12T10:11:04.267Z] PID 397 |     at Runner.runTest (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runner.js:681:10)
[task 2022-06-12T10:11:04.267Z] PID 397 |     at /builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runner.js:804:12
[task 2022-06-12T10:11:04.267Z] PID 397 |     at next (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runner.js:596:14)
[task 2022-06-12T10:11:04.267Z] PID 397 |     at /builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runner.js:606:7
[task 2022-06-12T10:11:04.267Z] PID 397 |     at next (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runner.js:489:14)
[task 2022-06-12T10:11:04.267Z] PID 397 |     at Immediate.<anonymous> (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runner.js:574:5)
[task 2022-06-12T10:11:04.267Z] PID 397 |     at processImmediate (internal/timers.js:461:21)
[task 2022-06-12T10:11:16.185Z] TEST-UNEXPECTED-TIMEOUT | Touchscreen should tap the button (touchscreen.spec.ts) | expected FAIL
[task 2022-06-12T10:11:16.185Z] TEST-INFO expected FAIL | took 20264ms
[task 2022-06-12T10:11:16.185Z] PID 397 | ["fail",{"title":"should tap the button","fullTitle":"Touchscreen should tap the button","file":"/builds/worker/checkouts/gecko/remote/test/puppeteer/test/touchscreen.spec.ts","duration":20007,"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/touchscreen.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/touchscreen.spec.ts)\n    at createTimeoutError (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/errors.js:498:15)\n    at Test.Runnable._timeoutError (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runnable.js:431:10)\n    at Timeout.<anonymous> (/builds/worker/checkouts/gecko/remote/test/puppeteer/node_modules/mocha/lib/runnable.js:246:24)\n    at listOnTimeout (internal/timers.js:554:17)\n    at processTimers (internal/timers.js:497:7)"}]
[task 2022-06-12T10:11:16.185Z] PID 397 | 1655028676185	CDP	TRACE	CDPConnection 6e800ec5-9d0b-47e5-a430-5222788e409e -> {"method":"Target.disposeBrowserContext","params":{"browserContextId":6},"id":21}
[task 2022-06-12T10:11:16.192Z] PID 397 | 1655028676191	CDP	TRACE	CDPConnection 6e800ec5-9d0b-47e5-a430-5222788e409e <- {"method":"Target.targetDestroyed","params":{"targetId":"83fa3ee4-8093-4801-9e78-65f390cf0e6e"}}
[task 2022-06-12T10:11:16.196Z] PID 397 | 1655028676195	CDP	TRACE	CDPConnection 6e800ec5-9d0b-47e5-a430-5222788e409e <- {"id":21,"result":{}}
[task 2022-06-12T10:11:16.197Z] TEST-START | Touchscreen should report touches (touchscreen.spec.ts)

The hang happened after a Page.reload command:
https://treeherder.mozilla.org/logviewer?job_id=381025755&repo=mozilla-beta&lineNumber=69881-69910

Here the log lines with the Target.receivedMessageFromTarget clutter removed:

`1655028656217	CDP	TRACE	CDPConnection %id% -> {"sessionId":"35c9b071-f37f-464b-939b-8bc644763046","method":"Page.reload","id":20}
`1655028656219	CDP	TRACE	CDPConnection %id% <- {"id":20,"result":{},"sessionId":"35c9b071-f37f-464b-939b-8bc644763046"}
`1655028656229	CDP	TRACE	CDPConnection %id% <- {"method":"Page.frameStartedLoading","params":{"frameId":"40"},"sessionId":"35c9b071-f37f-464b-939b-8bc644763046"}
`1655028656229	CDP	TRACE	CDPConnection %id% <- {"method":"Page.lifecycleEvent","params":{"frameId":"40","name":"init","timestamp":1655028656.223},"sessionId":"35c9b071-f37f-464b-939b-8bc644763046"}
`1655028656231	CDP	TRACE	CDPConnection %id% <- {"method":"Runtime.executionContextDestroyed","params":{"executionContextId":2},"sessionId":"35c9b071-f37f-464b-939b-8bc644763046"}
`1655028656231	CDP	TRACE	CDPConnection %id% <- {"method":"Runtime.executionContextDestroyed","params":{"executionContextId":3},"sessionId":"35c9b071-f37f-464b-939b-8bc644763046"}
`1655028656231	CDP	TRACE	CDPConnection %id% <- {"method":"Runtime.executionContextsCleared","params":{},"sessionId":"35c9b071-f37f-464b-939b-8bc644763046"}
`1655028656237	CDP	TRACE	CDPConnection %id% <- {"method":"Page.frameNavigated","params":{"frame":{"id":"40","url":"about:blank","securityOrigin":null,"mimeType":null}},"sessionId":"35c9b071-f37f-464b-939b-8bc644763046"}
`1655028656237	CDP	TRACE	CDPConnection %id% <- {"method":"Runtime.executionContextCreated","params":{"context":{"id":4,"origin":"null","name":"","auxData":{"isDefault":true,"frameId":"40","type":"default"}}},"sessionId":"35c9b071-f37f-464b-939b-8bc644763046"}
`1655028656238	CDP	TRACE	CDPConnection %id% <- {"method":"Runtime.executionContextCreated","params":{"context":{"id":5,"origin":"null","name":"__puppeteer_utility_world__","auxData":{"isDefault":false,"frameId":"40","type":"isolated"}}},"sessionId":"35c9b071-f37f-464b-939b-8bc644763046"}
`1655028656239	CDP	TRACE	CDPConnection %id% <- {"method":"Page.domContentEventFired","params":{"timestamp":1655028656.23},"sessionId":"35c9b071-f37f-464b-939b-8bc644763046"}
`1655028656240	CDP	TRACE	CDPConnection %id% <- {"method":"Page.lifecycleEvent","params":{"frameId":"40","name":"DOMContentLoaded","timestamp":1655028656.23},"sessionId":"35c9b071-f37f-464b-939b-8bc644763046"}
`1655028656240	CDP	TRACE	CDPConnection %id% <- {"method":"Page.loadEventFired","params":{"timestamp":1655028656.233},"sessionId":"35c9b071-f37f-464b-939b-8bc644763046"}
`1655028656240	CDP	TRACE	CDPConnection %id% <- {"method":"Page.lifecycleEvent","params":{"frameId":"40","name":"load","timestamp":1655028656.233},"sessionId":"35c9b071-f37f-464b-939b-8bc644763046"}
`1655028656240	CDP	TRACE	CDPConnection %id% <- {"method":"Page.frameStoppedLoading","params":{"frameId":"40"},"sessionId":"35c9b071-f37f-464b-939b-8bc644763046"}
`TimeoutError: waiting for target failed: timeout 30000ms exceeded

So a specific event Puppeteer might wait for here isn't getting fired. Lets observe how often this test fails.

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=388623810&repo=autoland&lineNumber=71595

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | Touchscreen should tap the button (touchscreen.spec.ts) | expected FAIL → Intermittent TEST-UNEXPECTED-TIMEOUT | Touchscreen should tap the button (touchscreen.spec.ts / .js) | expected FAIL

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: REOPENED → RESOLVED
Closed: 3 years ago → 2 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.