Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=275155243&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/VOiMtl3LS1CnFtNQi2dHiA/runs/0/artifacts/public/logs/live_backing.log

[task 2019-11-07T20:09:09.685Z] 20:09:09 INFO - TEST-PASS | remote/test/browser/page/browser_captureScreenshot.js | Size of quality 100 is larger than default -
[task 2019-11-07T20:09:09.689Z] 20:09:09 INFO - Buffered messages finished
[task 2019-11-07T20:09:09.690Z] 20:09:09 INFO - TEST-UNEXPECTED-FAIL | remote/test/browser/page/browser_captureScreenshot.js | Size of quality 10 is smaller than default -
[task 2019-11-07T20:09:09.691Z] 20:09:09 INFO - Stack trace:
[task 2019-11-07T20:09:09.692Z] 20:09:09 INFO - chrome://mochikit/content/browser-test.js:test_ok:1299
[task 2019-11-07T20:09:09.693Z] 20:09:09 INFO - chrome://mochitests/content/browser/remote/test/browser/page/browser_captureScreenshot.js:asJPEGFormatAndQuality:140
[task 2019-11-07T20:09:09.694Z] 20:09:09 INFO - chrome://mochitests/content/browser/remote/test/browser/head.js:this.add_task/<:42
[task 2019-11-07T20:09:09.695Z] 20:09:09 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1069
[task 2019-11-07T20:09:09.696Z] 20:09:09 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1104
[task 2019-11-07T20:09:09.697Z] 20:09:09 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:932
[task 2019-11-07T20:09:09.697Z] 20:09:09 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:805
[task 2019-11-07T20:09:09.698Z] 20:09:09 INFO - CDP client closed
[task 2019-11-07T20:09:09.700Z] 20:09:09 INFO - GECKO(2036) | 1573157349549 RemoteAgent INFO Stopped listening
[task 2019-11-07T20:09:09.703Z] 20:09:09 INFO - CDP server stopped
[task 2019-11-07T20:09:09.704Z] 20:09:09 INFO - Leaving test bound
[task 2019-11-07T20:09:09.704Z] 20:09:09 INFO - GECKO(2036) | MEMORY STAT | vsize 20975078MB | residentFast 1137MB
[task 2019-11-07T20:09:09.705Z] 20:09:09 INFO - TEST-OK | remote/test/browser/page/browser_captureScreenshot.js | took 7637ms

Pernosco session: https://pernos.co/debug/PcSVEvwigawYDjCYc5L32g/index.html

https://hg.mozilla.org/mozilla-central/rev/ce6090991688

Here the data related to those checks:

 0:09.18 INFO *** infoDefault lenght: 21020
 0:09.18 INFO *** info100 lenght: 38092
 0:09.18 PASS Size of quality 100 is larger than default -
 0:09.18 INFO *** info10 lenght: 21272

The content length of a jpeg image with 10% quality is larger than one with 80%. Maybe there is a baseline, or we didn't screenshot correctly. I will extract the images and upload them as reference in a moment.

The problem here is that the screenshot with default quality which is taken first, is blank! As such the 10% quality one which is taken some milliseconds later is larger because it contains the expected output.

That means that the suspicion from Matt was right, and we do not wait long enough for the data URL having finished loading.

What's strange is that we make use of BrowserTestUtils.loadURI in combination with BrowserTestUtils.browserLoaded():
https://searchfox.org/mozilla-central/source/remote/test/browser/head.js#168-173

Why aren't other mochitests broken which do the same? Maybe none of those make use of data URLs, and as such a required fix for browserLoaded() was missing? It clearly looks like a regression from bug 1593560 and especially https://hg.mozilla.org/integration/autoland/rev/bd4e2201c286.

I'm not sure what this change actually means, and for which additional events browserLoaded() would have to wait for now.

Gijs, or Matt could you please help?

(In reply to :Gijs (he/him) from comment #6)

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #5)

It clearly looks like a regression from bug 1593560 and especially https://hg.mozilla.org/integration/autoland/rev/bd4e2201c286.

Uh, really? that landed ages ago and this bug is new today. Why do you think this is the regressor?

Oh, sorry, I assumed this was the generic enabling of DocumentChannel. I don't know, then. The code in the utility function looks correct to me in the sense that it waits for the load. Perhaps it should be waiting for a paint event too?

Maybe, but now I have seen the problem. loadURL() in our head.js file is async, but the test doesn't use await! What a silly mistake.

I will have a look at all the existent tests to get this fixed. Sorry for the noise.

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

https://hg.mozilla.org/mozilla-central/rev/e7c129480d82

This is fixed now!