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

[task 2020-12-11T23:03:38.395Z] PID 390 | 1607727818394	RemoteAgent	TRACE	(connection {08e4a329-b5d4-4814-9b2e-92652c448cab})-> {"sessionId":"d51de3a8-febb-46d7-a58b-5ef44d725aa4","method":"Input.dispatchMouseEvent","params":{"type":"mouseReleased","button":"left","x":750,"y":260,"modifiers":0,"clickCount":1},"id":529}
[task 2020-12-11T23:03:38.396Z] PID 390 | 1607727818396	RemoteAgent	TRACE	<-(connection {08e4a329-b5d4-4814-9b2e-92652c448cab}) {"sessionId":"d51de3a8-febb-46d7-a58b-5ef44d725aa4","id":529,"result":{}}
[task 2020-12-11T23:03:38.397Z] PID 390 | 1607727818397	RemoteAgent	TRACE	<-(connection {08e4a329-b5d4-4814-9b2e-92652c448cab}) {"sessionId":"d51de3a8-febb-46d7-a58b-5ef44d725aa4","method":"Runtime.consoleAPICalled","params":{"args":[{"type":"string","value":"button #10 clicked"}],"executionContextId":3,"timestamp":1607727818396,"type":"log"}}
[task 2020-12-11T23:03:38.433Z] PID 390 | 1607727818433	RemoteAgent	TRACE	(connection {08e4a329-b5d4-4814-9b2e-92652c448cab})-> {"sessionId":"d51de3a8-febb-46d7-a58b-5ef44d725aa4","method":"Runtime.releaseObject","params":{"objectId":"d381b7a9-180b-41a6-bff6-7f738f632fc8"},"id":530}
[task 2020-12-11T23:03:38.434Z] PID 390 | 1607727818433	RemoteAgent	TRACE	<-(connection {08e4a329-b5d4-4814-9b2e-92652c448cab}) {"sessionId":"d51de3a8-febb-46d7-a58b-5ef44d725aa4","id":530,"result":{}}
[task 2020-12-11T23:03:38.435Z] TEST-UNEXPECTED-FAIL | Page.click should click offscreen buttons (click.spec.ts) | expected PASS
[task 2020-12-11T23:03:38.435Z] TEST-INFO took 1422ms
[task 2020-12-11T23:03:38.436Z] PID 390 | ["fail",{"title":"should click offscreen buttons","fullTitle":"Page.click should click offscreen buttons","file":"/builds/worker/checkouts/gecko/remote/test/puppeteer/test/click.spec.ts","duration":1179,"currentRetry":0,"err":"expect(received).toEqual(expected) // deep equality\n\n- Expected  - 0\n+ Received  + 1\n\n  Array [\n+   \"[Exception... \\\"Favicon at \\\"http://localhost:8907/favicon.ico\\\" failed to load: Not Found.\\\"  nsresult: \\\"0x80004005 (NS_ERROR_FAILURE)\\\"  location: \\\"JS frame :: resource:///modules/FaviconLoader.jsm :: onStopRequest :: line 253\\\"  data: no]\",\n    \"button #0 clicked\",\n    \"button #1 clicked\",\n    \"button #2 clicked\",\n    \"button #3 clicked\",\n    \"button #4 clicked\",\n    \"button #5 clicked\",\n    \"button #6 clicked\",\n    \"button #7 clicked\",\n    \"button #8 clicked\",\n    \"button #9 clicked\",\n    \"button #10 clicked\",\n  ]","stack":"Error: expect(received).toEqual(expected) // deep equality\n\n- Expected  - 0\n+ Received  + 1\n\n  Array [\n+   \"[Exception... \\\"Favicon at \\\"http://localhost:8907/favicon.ico\\\" failed to load: Not Found.\\\"  nsresult: \\\"0x80004005 (NS_ERROR_FAILURE)\\\"  location: \\\"JS frame :: resource:///modules/FaviconLoader.jsm :: onStopRequest :: line 253\\\"  data: no]\",\n    \"button #0 clicked\",\n    \"button #1 clicked\",\n    \"button #2 clicked\",\n    \"button #3 clicked\",\n    \"button #4 clicked\",\n    \"button #5 clicked\",\n    \"button #6 clicked\",\n    \"button #7 clicked\",\n    \"button #8 clicked\",\n    \"button #9 clicked\",\n    \"button #10 clicked\",\n  ]\n    at Context.it (/builds/worker/checkouts/gecko/remote/test/puppeteer/test/click.spec.ts:146:22)\n    at process._tickCallback (internal/process/next_tick.js:68:7)"}]
[task 2020-12-11T23:03:38.436Z] PID 390 | 1607727818435	RemoteAgent	TRACE	(connection {08e4a329-b5d4-4814-9b2e-92652c448cab})-> {"method":"Target.disposeBrowserContext","params":{"browserContextId":15},"id":531}
[task 2020-12-11T23:03:38.442Z] PID 390 | 1607727818441	RemoteAgent	TRACE	<-(connection {08e4a329-b5d4-4814-9b2e-92652c448cab}) {"method":"Target.targetDestroyed","params":{"targetId":"1b7fcd7c-c738-48b7-b5d1-3cd4fc84921b"}}
[task 2020-12-11T23:03:38.446Z] PID 390 | 1607727818445	RemoteAgent	TRACE	<-(connection {08e4a329-b5d4-4814-9b2e-92652c448cab}) {"id":531,"result":{}}


----------------[task 2020-12-11T23:03:37.013Z] TEST-START | Page.click should click offscreen buttons (click.spec.ts)-------------```

This failure started on Dec 11th. The test is here:
https://searchfox.org/mozilla-central/rev/bd92b9b4a3c2ff022e830c1358968a84e6e69c95/remote/test/puppeteer/test/click.spec.ts#135-159

Note that the test relies on console.log() events as sent by offscreenbuttons.html.

With bug 1553854 the test has been marked as expected pass.

It's interesting that all console.log events have been received, but due to the missing output of failure details it's not clear to me what's actually failing. It would need further investigation.

The problem here is that we get a missing favicon.ico error logged first via Log.entryAdded:

0:32.48 pid:88492 1613027644047 RemoteAgent TRACE <-(connection {9f8c3187-6062-3741-86df-4a7fbd78906d}) {"sessionId":"dbbeb56e-c080-2f48-9ab3-dfd8fcaddc8c","method":"Log.entryAdded","params":{"entry":{"source":"other","level":"error","text":"[Exception... "Favicon at "http://localhost:8907/favicon.ico" failed to load: Not Found." nsresult: "0x80004005 (NS_ERROR_FAILURE)" location: "JS frame :: resource:///modules/FaviconLoader.jsm :: onStopRequest :: line 253" data: no]","timestamp":1613027644044,"url":"","lineNumber":0}}}

Running the same test with Chrome actually also fails:

0:30.55 pid:89653 2021-02-11T07:22:27.666Z puppeteer:protocol:RECV ◀ {"method":"Log.entryAdded","params":{"entry":{"source":"network","level":"error","text":"Failed to load resource: the server responded with a status of 404 (Not Found)","timestamp":1.613028147664699e+12,"url":"http://localhost:8907/favicon.ico","networkRequestId":"89681.2"}},"sessionId":"7C8795DD023B7FA1FB8397807B2F7097"

As such I wonder why that is a problem for us not for tests running in Puppeteer CI.

When I add a favicon.ico file to test/assets/ it all works fine.

Mathias, any idea why this fails for us? Should we just add a favicon.ico to the assets in the Puppeteer repo?

I considered adding an explicit <link rel=icon> to this test specifically at first, but adding a favicon.ico and relying on the browser automatically fetching it per the HTML Standard indeed seems like a better approach, since it prevents similar issues in any other tests. Upstream patch: https://github.com/puppeteer/puppeteer/pull/6868

Fantastic. So I will use the same favicon for our in-tree copy of Puppeteer 5.50.

https://hg.mozilla.org/mozilla-central/rev/045d91aa8b2f

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=346203729&repo=mozilla-central&lineNumber=3167

Mistakenly reopened, closing again as fixed.