1671592 - Intermittent dom/base/test/test_bug1639328.html | display-none-http - got true, expected false | display-none-https - got true, expected false

Status: RESOLVED FIXED

(Core :: DOM: Core & HTML, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=318824160&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/aj8DmpPARmmigu1OlBaIUw/runs/0/artifacts/public/logs/live_backing.log

---

[task 2020-10-16T11:39:00.637Z] 11:39:00     INFO - TEST-START | dom/base/test/test_bug1639328.html
[task 2020-10-16T11:39:01.063Z] 11:39:01     INFO - GECKO(1511) | [3244, Unnamed thread 7efe4535d5e0] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:202
[task 2020-10-16T11:39:01.064Z] 11:39:01     INFO - GECKO(1511) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmp1M3gyA.mozrunner/runtests_leaks.log
[task 2020-10-16T11:39:01.066Z] 11:39:01     INFO - GECKO(1511) | [3244, Unnamed thread 7efe4535d5e0] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:202
[task 2020-10-16T11:39:01.069Z] 11:39:01     INFO - GECKO(1511) | [3244, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:247
[task 2020-10-16T11:39:01.432Z] 11:39:01     INFO - GECKO(1511) | [Child 3244, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:626
[task 2020-10-16T11:39:02.097Z] 11:39:02     INFO - TEST-INFO | started process screentopng
[task 2020-10-16T11:39:02.545Z] 11:39:02     INFO - TEST-INFO | screentopng: exit 0
[task 2020-10-16T11:39:02.545Z] 11:39:02     INFO - Buffered messages logged at 11:39:01
[task 2020-10-16T11:39:02.545Z] 11:39:02     INFO - TEST-PASS | dom/base/test/test_bug1639328.html | Should not be throttling main page 
[task 2020-10-16T11:39:02.546Z] 11:39:02     INFO - querying https://example.com/tests/dom/base/test/file_bug1639328.html
[task 2020-10-16T11:39:02.546Z] 11:39:02     INFO - got {"throttledFrameRequests":false}
[task 2020-10-16T11:39:02.546Z] 11:39:02     INFO - TEST-PASS | dom/base/test/test_bug1639328.html | http 
[task 2020-10-16T11:39:02.546Z] 11:39:02     INFO - Switching display of http
[task 2020-10-16T11:39:02.546Z] 11:39:02     INFO - querying https://example.com/tests/dom/base/test/file_bug1639328.html
[task 2020-10-16T11:39:02.546Z] 11:39:02     INFO - got {"throttledFrameRequests":true}
[task 2020-10-16T11:39:02.547Z] 11:39:02     INFO - TEST-PASS | dom/base/test/test_bug1639328.html | http 
[task 2020-10-16T11:39:02.547Z] 11:39:02     INFO - And switching display back for http
[task 2020-10-16T11:39:02.547Z] 11:39:02     INFO - querying https://example.com/tests/dom/base/test/file_bug1639328.html
[task 2020-10-16T11:39:02.548Z] 11:39:02     INFO - got {"throttledFrameRequests":false}
[task 2020-10-16T11:39:02.549Z] 11:39:02     INFO - TEST-PASS | dom/base/test/test_bug1639328.html | http 
[task 2020-10-16T11:39:02.550Z] 11:39:02     INFO - querying https://example.com/tests/dom/base/test/file_bug1639328.html
[task 2020-10-16T11:39:02.551Z] 11:39:02     INFO - got {"throttledFrameRequests":false}
[task 2020-10-16T11:39:02.552Z] 11:39:02     INFO - TEST-PASS | dom/base/test/test_bug1639328.html | https 
[task 2020-10-16T11:39:02.552Z] 11:39:02     INFO - Switching display of https
[task 2020-10-16T11:39:02.556Z] 11:39:02     INFO - querying https://example.com/tests/dom/base/test/file_bug1639328.html
[task 2020-10-16T11:39:02.557Z] 11:39:02     INFO - got {"throttledFrameRequests":true}
[task 2020-10-16T11:39:02.558Z] 11:39:02     INFO - TEST-PASS | dom/base/test/test_bug1639328.html | https 
[task 2020-10-16T11:39:02.558Z] 11:39:02     INFO - And switching display back for https
[task 2020-10-16T11:39:02.559Z] 11:39:02     INFO - querying https://example.com/tests/dom/base/test/file_bug1639328.html
[task 2020-10-16T11:39:02.559Z] 11:39:02     INFO - got {"throttledFrameRequests":false}
[task 2020-10-16T11:39:02.560Z] 11:39:02     INFO - TEST-PASS | dom/base/test/test_bug1639328.html | https 
[task 2020-10-16T11:39:02.561Z] 11:39:02     INFO - querying http://mochi.test:8888/tests/dom/base/test/file_bug1639328.html
[task 2020-10-16T11:39:02.561Z] 11:39:02     INFO - got {"throttledFrameRequests":false}
[task 2020-10-16T11:39:02.562Z] 11:39:02     INFO - TEST-PASS | dom/base/test/test_bug1639328.html | same-origin 
[task 2020-10-16T11:39:02.563Z] 11:39:02     INFO - Switching display of same-origin
[task 2020-10-16T11:39:02.565Z] 11:39:02     INFO - querying http://mochi.test:8888/tests/dom/base/test/file_bug1639328.html
[task 2020-10-16T11:39:02.566Z] 11:39:02     INFO - got {"throttledFrameRequests":true}
[task 2020-10-16T11:39:02.569Z] 11:39:02     INFO - TEST-PASS | dom/base/test/test_bug1639328.html | same-origin 
[task 2020-10-16T11:39:02.569Z] 11:39:02     INFO - And switching display back for same-origin
[task 2020-10-16T11:39:02.570Z] 11:39:02     INFO - querying http://mochi.test:8888/tests/dom/base/test/file_bug1639328.html
[task 2020-10-16T11:39:02.571Z] 11:39:02     INFO - got {"throttledFrameRequests":false}
[task 2020-10-16T11:39:02.572Z] 11:39:02     INFO - TEST-PASS | dom/base/test/test_bug1639328.html | same-origin 
[task 2020-10-16T11:39:02.572Z] 11:39:02     INFO - querying https://example.com/tests/dom/base/test/file_bug1639328.html
[task 2020-10-16T11:39:02.573Z] 11:39:02     INFO - Buffered messages logged at 11:39:02
[task 2020-10-16T11:39:02.574Z] 11:39:02     INFO - got {"throttledFrameRequests":true}
[task 2020-10-16T11:39:02.575Z] 11:39:02     INFO - TEST-PASS | dom/base/test/test_bug1639328.html | display-none-http 
[task 2020-10-16T11:39:02.576Z] 11:39:02     INFO - Switching display of display-none-http
[task 2020-10-16T11:39:02.576Z] 11:39:02     INFO - querying https://example.com/tests/dom/base/test/file_bug1639328.html
[task 2020-10-16T11:39:02.577Z] 11:39:02     INFO - got {"throttledFrameRequests":true}
[task 2020-10-16T11:39:02.578Z] 11:39:02     INFO - Buffered messages finished
[task 2020-10-16T11:39:02.579Z] 11:39:02     INFO - TEST-UNEXPECTED-FAIL | dom/base/test/test_bug1639328.html | display-none-http - got true, expected false
[task 2020-10-16T11:39:02.580Z] 11:39:02     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:500:14
[task 2020-10-16T11:39:02.581Z] 11:39:02     INFO -     checkFrame@dom/base/test/test_bug1639328.html:42:5
[task 2020-10-16T11:39:02.581Z] 11:39:02     INFO - And switching display back for display-none-http
[task 2020-10-16T11:39:02.582Z] 11:39:02     INFO - querying https://example.com/tests/dom/base/test/file_bug1639328.html
[task 2020-10-16T11:39:02.583Z] 11:39:02     INFO - got {"throttledFrameRequests":true}
[task 2020-10-16T11:39:02.584Z] 11:39:02     INFO - TEST-PASS | dom/base/test/test_bug1639328.html | display-none-http 
[task 2020-10-16T11:39:02.584Z] 11:39:02     INFO - querying https://example.com/tests/dom/base/test/file_bug1639328.html
[task 2020-10-16T11:39:02.585Z] 11:39:02     INFO - got {"throttledFrameRequests":true}
[task 2020-10-16T11:39:02.586Z] 11:39:02     INFO - TEST-PASS | dom/base/test/test_bug1639328.html | display-none-https 
[task 2020-10-16T11:39:02.587Z] 11:39:02     INFO - Switching display of display-none-https
[task 2020-10-16T11:39:02.588Z] 11:39:02     INFO - querying https://example.com/tests/dom/base/test/file_bug1639328.html
[task 2020-10-16T11:39:02.589Z] 11:39:02     INFO - got {"throttledFrameRequests":true}
[task 2020-10-16T11:39:02.590Z] 11:39:02     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-10-16T11:39:02.590Z] 11:39:02     INFO - TEST-UNEXPECTED-FAIL | dom/base/test/test_bug1639328.html | display-none-https - got true, expected false
[task 2020-10-16T11:39:02.591Z] 11:39:02     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:500:14
[task 2020-10-16T11:39:02.592Z] 11:39:02     INFO -     checkFrame@dom/base/test/test_bug1639328.html:42:5
[task 2020-10-16T11:39:02.593Z] 11:39:02     INFO - And switching display back for display-none-https
[task 2020-10-16T11:39:02.594Z] 11:39:02     INFO - querying https://example.com/tests/dom/base/test/file_bug1639328.html
[task 2020-10-16T11:39:02.595Z] 11:39:02     INFO - got {"throttledFrameRequests":true}
[task 2020-10-16T11:39:02.595Z] 11:39:02     INFO - TEST-PASS | dom/base/test/test_bug1639328.html | display-none-https 
[task 2020-10-16T11:39:02.595Z] 11:39:02     INFO - querying http://mochi.test:8888/tests/dom/base/test/file_bug1639328.html
[task 2020-10-16T11:39:02.595Z] 11:39:02     INFO - got {"throttledFrameRequests":true}
[task 2020-10-16T11:39:02.596Z] 11:39:02     INFO - TEST-PASS | dom/base/test/test_bug1639328.html | display-none-same-origin 
[task 2020-10-16T11:39:02.596Z] 11:39:02     INFO - Switching display of display-none-same-origin
[task 2020-10-16T11:39:02.596Z] 11:39:02     INFO - querying http://mochi.test:8888/tests/dom/base/test/file_bug1639328.html
[task 2020-10-16T11:39:02.596Z] 11:39:02     INFO - got {"throttledFrameRequests":false}
[task 2020-10-16T11:39:02.596Z] 11:39:02     INFO - TEST-PASS | dom/base/test/test_bug1639328.html | display-none-same-origin 
[task 2020-10-16T11:39:02.596Z] 11:39:02     INFO - And switching display back for display-none-same-origin
[task 2020-10-16T11:39:02.596Z] 11:39:02     INFO - querying http://mochi.test:8888/tests/dom/base/test/file_bug1639328.html
[task 2020-10-16T11:39:02.596Z] 11:39:02     INFO - got {"throttledFrameRequests":true}
[task 2020-10-16T11:39:02.597Z] 11:39:02     INFO - TEST-PASS | dom/base/test/test_bug1639328.html | display-none-same-origin 
[task 2020-10-16T11:39:02.597Z] 11:39:02     INFO - GECKO(1511) | MEMORY STAT | vsize 2967MB | residentFast 242MB | heapAllocated 21MB
[task 2020-10-16T11:39:02.752Z] 11:39:02     INFO - TEST-OK | dom/base/test/test_bug1639328.html | took 2110ms```

Comment 1

[Emilio Cobos Álvarez (:emilio)]

Per bug 1664255 etc, I think this was regressed by bug 1669239... I think the test may be running an extra RAF callback synchronously after the changes in that bug, and we may need to wait for it, or do something else...

Comment 2

[Sean Feng [:sefeng]]

Attachment: Bug 1671592 - Remove PuppetWidget::PaintTask and PuppetWidget::Paint r=emilio

After Bug 1669239, The way we use PuppetWidget::Paint starts to be
more async. For instance, PuppetWidget::Invalidate will schedule
an async PaintTask, when the PaintTask runs, it'll request
the next Tick to paint which is also async.

It starts to cause some tests to fail because of the timing. This
patch just improves the overall usage to be less async.

Comment 3

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/f180b1c3e846
Remove PuppetWidget::PaintTask and PuppetWidget::Paint r=emilio

Comment 4

[Narcis Beleuzu [:NarcisB]]

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

Comment 5

[Intermittent Failures Robot]

5 failures in 3694 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 5

Platform breakdown:

• linux1804-64-qr: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1671592&startday=2020-10-12&endday=2020-10-18&tree=all

Comment 7

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

This failure has been observed once today.

Sean, please take a look if there is anything left to be done here.

Comment 8

[Sean Feng [:sefeng]]

We have a fix in mind that can be landed easily. However, it looks like we are not getting any new crashes in the past few days, so I think I'll just keep it as it for now.

The failures don't correspond to any bugs, it's the test doesn't wait long enough here.

Please NI me when this occurs again and I'll get a patch up.