1645495 - Intermittent browser/components/resistfingerprinting/test/browser/browser_timing_precision_cross_origin_isolated.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N)

Status: RESOLVED FIXED

(Core :: Security, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-06-12T16:53:35.071Z] 16:53:35 INFO - TEST-START | browser/components/resistfingerprinting/test/browser/browser_timing_precision_cross_origin_isolated.js
[task 2020-06-12T16:53:41.983Z] 16:53:41 INFO - GECKO(10144) | IPDL protocol error: Handler returned error code!
[task 2020-06-12T16:53:41.983Z] 16:53:41 INFO - GECKO(10144) | ###!!! [Parent][DispatchAsyncMessage] Error: PLayerTransaction::Msg_ReleaseLayer Processing error: message was deserialized, but the handler returned false (indicating failure)
[task 2020-06-12T16:53:41.983Z] 16:53:41 INFO - GECKO(10144) | IPDL protocol error: Handler returned error code!
[task 2020-06-12T16:53:41.984Z] 16:53:41 INFO - GECKO(10144) | ###!!! [Parent][DispatchAsyncMessage] Error: PLayerTransaction::Msg_ReleaseLayer Processing error: message was deserialized, but the handler returned false (indicating failure)
[task 2020-06-12T16:53:42.002Z] 16:53:42 INFO - GECKO(10144) | JavaScript error: resource:///actors/ContentSearchParent.jsm, line 629: TypeError: can't access property "addEventListener", browser is null
[task 2020-06-12T16:53:43.911Z] 16:53:43 INFO - GECKO(10144) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-06-12T16:53:49.772Z] 16:53:49 INFO - GECKO(10144) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-06-12T16:53:51.971Z] 16:53:51 INFO - GECKO(10144) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-06-12T16:53:59.682Z] 16:53:59 INFO - GECKO(10144) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-06-12T16:54:01.230Z] 16:54:01 INFO - GECKO(10144) | IPDL protocol error: Handler returned error code!
[task 2020-06-12T16:54:01.230Z] 16:54:01 INFO - GECKO(10144) | ###!!! [Parent][DispatchAsyncMessage] Error: PLayerTransaction::Msg_ReleaseLayer Processing error: message was deserialized, but the handler returned false (indicating failure)
[task 2020-06-12T16:54:01.230Z] 16:54:01 INFO - GECKO(10144) | IPDL protocol error: Handler returned error code!
[task 2020-06-12T16:54:01.230Z] 16:54:01 INFO - GECKO(10144) | ###!!! [Parent][DispatchAsyncMessage] Error: PLayerTransaction::Msg_ReleaseLayer Processing error: message was deserialized, but the handler returned false (indicating failure)
[task 2020-06-12T16:54:01.262Z] 16:54:01 INFO - GECKO(10144) | JavaScript error: resource:///actors/ContentSearchParent.jsm, line 629: TypeError: can't access property "addEventListener", browser is null
[task 2020-06-12T16:54:09.335Z] 16:54:09 INFO - GECKO(10144) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-06-12T16:54:21.223Z] 16:54:21 INFO - TEST-INFO | started process screenshot
[task 2020-06-12T16:54:21.303Z] 16:54:21 INFO - TEST-INFO | screenshot: exit 0
[task 2020-06-12T16:54:21.304Z] 16:54:21 INFO - Buffered messages logged at 16:53:35
[task 2020-06-12T16:54:21.304Z] 16:54:21 INFO - Entering test bound runTestsForWorker
[task 2020-06-12T16:54:21.305Z] 16:54:21 INFO - Buffered messages logged at 16:53:41
[task 2020-06-12T16:54:21.306Z] 16:54:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_timing_precision_cross_origin_isolated.js | In a worker, for reduceTimerPrecision, performance.timeOrigin is not correctly rounded: 1591980821700 - true == true - [task 2020-06-12T16:54:21.307Z] 16:54:21 INFO - Console message: [JavaScript Error: "TypeError: can't access property "addEventListener", browser is null" {file: "resource:///actors/ContentSearchParent.jsm" line: 629}]
[task 2020-06-12T16:54:21.307Z] 16:54:21 INFO - receiveMessage@resource:///actors/ContentSearchParent.jsm:629:5
[task 2020-06-12T16:54:21.307Z] 16:54:21 INFO - JSActor queryhandleEvent@resource:///actors/ContentSearchChild.jsm:14:12
[task 2020-06-12T16:54:21.308Z] 16:54:21 INFO - _sendMsg@chrome://browser/content/contentSearchHandoffUI.js:70:18
[task 2020-06-12T16:54:21.308Z] 16:54:21 INFO - ContentSearchHandoffUIController@chrome://browser/content/contentSearchHandoffUI.js:12:8
[task 2020-06-12T16:54:21.308Z] 16:54:21 INFO - onInputMountHandoff@resource://activity-stream/data/content/activity-stream.bundle.js:11246:39
[task 2020-06-12T16:54:21.308Z] 16:54:21 INFO - Aj@resource://activity-stream/vendor/react-dom.js:161:87
[task 2020-06-12T16:54:21.308Z] 16:54:21 INFO - unstable_runWithPriority@resource://activity-stream/vendor/react.js:25:260
[task 2020-06-12T16:54:21.309Z] 16:54:21 INFO - Da@resource://activity-stream/vendor/react-dom.js:60:280
[task 2020-06-12T16:54:21.309Z] 16:54:21 INFO - ab@resource://activity-stream/vendor/react-dom.js:154:192
[task 2020-06-12T16:54:21.309Z] 16:54:21 INFO - Te@resource://activity-stream/vendor/react-dom.js:146:357
[task 2020-06-12T16:54:21.309Z] 16:54:21 INFO - Pg/<@resource://activity-stream/vendor/react-dom.js:61:68
[task 2020-06-12T16:54:21.309Z] 16:54:21 INFO - unstable_runWithPriority@resource://activity-stream/vendor/react.js:25:260
[task 2020-06-12T16:54:21.310Z] 16:54:21 INFO - Da@resource://activity-stream/vendor/react-dom.js:60:280
[task 2020-06-12T16:54:21.310Z] 16:54:21 INFO - Pg@resource://activity-stream/vendor/react-dom.js:61:16
[task 2020-06-12T16:54:21.310Z] 16:54:21 INFO - ha@resource://activity-stream/vendor/react-dom.js:60:451
[task 2020-06-12T16:54:21.310Z] 16:54:21 INFO - Qh@resource://activity-stream/vendor/react-dom.js:147:10
[task 2020-06-12T16:54:21.310Z] 16:54:21 INFO - notify@resource://activity-stream/vendor/react-redux.js:1:1922
[task 2020-06-12T16:54:21.311Z] 16:54:21 INFO - t.notifyNestedSubs@resource://activity-stream/vendor/react-redux.js:1:1499
[task 2020-06-12T16:54:21.311Z] 16:54:21 INFO - t.handleChangeWrapper@resource://activity-stream/vendor/react-redux.js:1:1567
[task 2020-06-12T16:54:21.311Z] 16:54:21 INFO - dispatch@resource://activity-stream/vendor/redux.js:339:20[task 2020-06-12T16:54:21.312Z] 16:54:21 INFO - NewtabRenderUtils</</messageMiddleware/</<@resource://activity-stream/data/content/activity-stream.bundle.js:2753:9
[task 2020-06-12T16:54:21.312Z] 16:54:21 INFO - NewtabRenderUtils</</queueEarlyMessageMiddleware/</<@resource://activity-stream/data/content/activity-stream.bundle.js:2818:11
[task 2020-06-12T16:54:21.312Z] 16:54:21 INFO - NewtabRenderUtils</</rehydrationMiddleware/</<@resource://activity-stream/data/content/activity-stream.bundle.js:2779:14
[task 2020-06-12T16:54:21.312Z] 16:54:21 INFO - NewtabRenderUtils</</initStore/<@resource://activity-stream/data/content/activity-stream.bundle.js:2845:15
[task 2020-06-12T16:54:21.313Z] 16:54:21 INFO - callListeners@resource://gre/modules/remotepagemanager/MessagePort.jsm:36:17
[task 2020-06-12T16:54:21.313Z] 16:54:21 INFO - handleMessage@resource://gre/modules/remotepagemanager/RemotePageManagerChild.jsm:78:19
[task 2020-06-12T16:54:21.313Z] 16:54:21 INFO - message@resource://gre/modules/remotepagemanager/MessagePort.jsm:203:10
[task 2020-06-12T16:54:21.314Z] 16:54:21 INFO - MessageListener.receiveMessageaddMessageListeners@resource://gre/modules/remotepagemanager/MessagePort.jsm:91:25
[task 2020-06-12T16:54:21.314Z] 16:54:21 INFO - MessagePort@resource://gre/modules/remotepagemanager/MessagePort.jsm:83:10
[task 2020-06-12T16:54:21.314Z] 16:54:21 INFO - ChildMessagePort@resource://gre/modules/remotepagemanager/RemotePageManagerChild.jsm:19:5
[task 2020-06-12T16:54:21.314Z] 16:54:21 INFO - observe@chrome://global/content/process-content.js:70:9
[task 2020-06-12T16:54:21.315Z] 16:54:21 INFO -
[task 2020-06-12T16:54:21.315Z] 16:54:21 INFO - Buffered messages logged at 16:53:43[task 2020-06-12T16:54:21.330Z] 16:54:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_timing_precision_cross_origin_isolated.js | webCOOP+COEP=https://example.com expected to be coop+coep -
[task 2020-06-12T16:54:21.331Z] 16:54:21 INFO - Leaving test bound runTestsForWorker
[task 2020-06-12T16:54:21.331Z] 16:54:21 INFO - Entering test bound runRTPTestDOM
[task 2020-06-12T16:54:21.332Z] 16:54:21 INFO - Buffered messages logged at 16:53:51
[task 2020-06-12T16:54:21.332Z] 16:54:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_timing_precision_cross_origin_isolated.js | Should be rounded to nearest 100 ms; saw 200 - true == true - [task 2020-06-12T16:54:21.341Z] 16:54:21 INFO - Console message: [JavaScript Error: "TypeError: can't access property "addEventListener", browser is null" {file: "resource:///actors/ContentSearchParent.jsm" line: 629}]
[task 2020-06-12T16:54:21.342Z] 16:54:21 INFO - receiveMessage@resource:///actors/ContentSearchParent.jsm:629:5
[task 2020-06-12T16:54:21.342Z] 16:54:21 INFO - JSActor queryhandleEvent@resource:///actors/ContentSearchChild.jsm:14:12
[task 2020-06-12T16:54:21.342Z] 16:54:21 INFO - _sendMsg@chrome://browser/content/contentSearchHandoffUI.js:70:18
[task 2020-06-12T16:54:21.342Z] 16:54:21 INFO - ContentSearchHandoffUIController@chrome://browser/content/contentSearchHandoffUI.js:12:8
[task 2020-06-12T16:54:21.342Z] 16:54:21 INFO - onInputMountHandoff@resource://activity-stream/data/content/activity-stream.bundle.js:11246:39
[task 2020-06-12T16:54:21.342Z] 16:54:21 INFO - Aj@resource://activity-stream/vendor/react-dom.js:161:87
[task 2020-06-12T16:54:21.342Z] 16:54:21 INFO - unstable_runWithPriority@resource://activity-stream/vendor/react.js:25:260
[task 2020-06-12T16:54:21.342Z] 16:54:21 INFO - Da@resource://activity-stream/vendor/react-dom.js:60:280
[task 2020-06-12T16:54:21.342Z] 16:54:21 INFO - ab@resource://activity-stream/vendor/react-dom.js:154:192
[task 2020-06-12T16:54:21.342Z] 16:54:21 INFO - Te@resource://activity-stream/vendor/react-dom.js:146:357
[task 2020-06-12T16:54:21.342Z] 16:54:21 INFO - Pg/<@resource://activity-stream/vendor/react-dom.js:61:68
[task 2020-06-12T16:54:21.342Z] 16:54:21 INFO - unstable_runWithPriority@resource://activity-stream/vendor/react.js:25:260
[task 2020-06-12T16:54:21.343Z] 16:54:21 INFO - Da@resource://activity-stream/vendor/react-dom.js:60:280
[task 2020-06-12T16:54:21.343Z] 16:54:21 INFO - Pg@resource://activity-stream/vendor/react-dom.js:61:16
[task 2020-06-12T16:54:21.343Z] 16:54:21 INFO - ha@resource://activity-stream/vendor/react-dom.js:60:451
[task 2020-06-12T16:54:21.343Z] 16:54:21 INFO - Qh@resource://activity-stream/vendor/react-dom.js:147:10
[task 2020-06-12T16:54:21.343Z] 16:54:21 INFO - notify@resource://activity-stream/vendor/react-redux.js:1:1922
[task 2020-06-12T16:54:21.343Z] 16:54:21 INFO - t.notifyNestedSubs@resource://activity-stream/vendor/react-redux.js:1:1499
[task 2020-06-12T16:54:21.343Z] 16:54:21 INFO - t.handleChangeWrapper@resource://activity-stream/vendor/react-redux.js:1:1567
[task 2020-06-12T16:54:21.343Z] 16:54:21 INFO - dispatch@resource://activity-stream/vendor/redux.js:339:20
[task 2020-06-12T16:54:21.343Z] 16:54:21 INFO - NewtabRenderUtils</</messageMiddleware/</<@resource://activity-stream/data/content/activity-stream.bundle.js:2753:9
[task 2020-06-12T16:54:21.343Z] 16:54:21 INFO - NewtabRenderUtils</</queueEarlyMessageMiddleware/</<@resource://activity-stream/data/content/activity-stream.bundle.js:2818:11
[task 2020-06-12T16:54:21.343Z] 16:54:21 INFO - NewtabRenderUtils</</rehydrationMiddleware/</<@resource://activity-stream/data/content/activity-stream.bundle.js:2779:14
[task 2020-06-12T16:54:21.343Z] 16:54:21 INFO - NewtabRenderUtils</</initStore/<@resource://activity-stream/data/content/activity-stream.bundle.js:2845:15
[task 2020-06-12T16:54:21.343Z] 16:54:21 INFO - callListeners@resource://gre/modules/remotepagemanager/MessagePort.jsm:36:17
[task 2020-06-12T16:54:21.343Z] 16:54:21 INFO - handleMessage@resource://gre/modules/remotepagemanager/RemotePageManagerChild.jsm:78:19[task 2020-06-12T16:54:21.343Z] 16:54:21 INFO - message@resource://gre/modules/remotepagemanager/MessagePort.jsm:203:10
[task 2020-06-12T16:54:21.343Z] 16:54:21 INFO - MessageListener.receiveMessageaddMessageListeners@resource://gre/modules/remotepagemanager/MessagePort.jsm:91:25
[task 2020-06-12T16:54:21.343Z] 16:54:21 INFO - MessagePort@resource://gre/modules/remotepagemanager/MessagePort.jsm:83:10
[task 2020-06-12T16:54:21.344Z] 16:54:21 INFO - ChildMessagePort@resource://gre/modules/remotepagemanager/RemotePageManagerChild.jsm:19:5
[task 2020-06-12T16:54:21.344Z] 16:54:21 INFO - observe@chrome://global/content/process-content.js:70:9[task 2020-06-12T16:54:21.349Z] 16:54:21 INFO - Buffered messages logged at 16:54:20
[task 2020-06-12T16:54:21.349Z] 16:54:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_timing_precision_cross_origin_isolated.js | The result of performance.now() should be rounded to nearest 0.005 ms in workers; saw 75.1 - true == true -
[task 2020-06-12T16:54:21.349Z] 16:54:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_timing_precision_cross_origin_isolated.js | The result of new Date().getTime() should be rounded to nearest 0.005 ms in workers; saw 1591980860988 - true == true -
[task 2020-06-12T16:54:21.350Z] 16:54:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_timing_precision_cross_origin_isolated.js | The result of new Event("").timeStamp should be rounded to nearest 0.005 ms in workers; saw 76.14 - true == true -
[task 2020-06-12T16:54:21.350Z] 16:54:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_timing_precision_cross_origin_isolated.js | The result of new File([], "").lastModified should be rounded to nearest 0.005 ms in workers; saw 1591980860989 - true == true -
[task 2020-06-12T16:54:21.350Z] 16:54:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_timing_precision_cross_origin_isolated.js | webCOOP+COEP=https://example.com expected to be coop+coep -
[task 2020-06-12T16:54:21.350Z] 16:54:21 INFO - Buffered messages logged at 16:54:21
[task 2020-06-12T16:54:21.350Z] 16:54:21 INFO - Leaving test bound runRTPTestsForWorker
[task 2020-06-12T16:54:21.350Z] 16:54:21 INFO - Buffered messages finished
[task 2020-06-12T16:54:21.351Z] 16:54:21 INFO - TEST-UNEXPECTED-FAIL | browser/components/resistfingerprinting/test/browser/browser_timing_precision_cross_origin_isolated.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -

Comment 1

[Intermittent Failures Robot]

2 failures in 5211 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2

Platform breakdown:

• windows10-64-ccov: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1645495&startday=2020-06-08&endday=2020-06-14&tree=all

Comment 2

[Intermittent Failures Robot]

16 failures in 784 pushes (0.02 failures/push) were associated with this bug yesterday.

Repository breakdown:

• try: 2
• autoland: 9
• mozilla-central: 5

Platform breakdown:

• linux1804-64-asan: 1
• linux1804-64: 12
• linux1804-64-ccov: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1645495&startday=2020-06-15&endday=2020-06-15&tree=all

Comment 3

[Intermittent Failures Robot]

26 failures in 874 pushes (0.03 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 13
• mozilla-central: 9
• try: 4

Platform breakdown:

• linux1804-64: 19
• linux1804-64-ccov: 4
• windows10-64-ccov: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1645495&startday=2020-06-16&endday=2020-06-16&tree=all

Comment 4

[Intermittent Failures Robot]

37 failures in 942 pushes (0.039 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 19
• mozilla-central: 14
• try: 4

Platform breakdown:

• linux1804-64: 27
• windows10-64-shippable-qr: 1
• linux1804-64-ccov: 5
• windows10-64-ccov: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1645495&startday=2020-06-17&endday=2020-06-17&tree=all

Comment 5

[Cosmin Sabou [:CosminS]]

This looks to be have spiked in failure rate from Bug 1621677. Tom, could you please have a look?
https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=e459bd0a9c55f3c61ed18c71796f1594a2c9a260&selectedTaskRun=SUN3OQvuSkqh1LhtbW6XGg.0&searchStr=Linux%2C18.04%2Cx64%2Cdebug%2Ctest-linux1804-64%2Fdebug-test-verify-e10s%2C%28TV%29

Comment 6

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1621677

Comment 7

[Tom Tung [:tt, :ttung]]

It looks like it's because there are too many test cases. I will split it up into different tests.

Comment 8

[Intermittent Failures Robot]

31 failures in 872 pushes (0.036 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 27
• mozilla-central: 3
• try: 1

Platform breakdown:

• linux1804-64: 29
• linux1804-64-ccov: 2

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

Comment 9

[Tom Tung [:tt, :ttung]]

Attachment: Bug 1645495 - Split up browser_timing_precision_cross_origin_isolated.js into different tests;

Comment 10

[Tom Tung [:tt, :ttung]]

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

Comment 11

[Intermittent Failures Robot]

20 failures in 339 pushes (0.059 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 9
• try: 3
• mozilla-central: 8

Platform breakdown:

• linux1804-64: 14
• linux1804-64-ccov: 5
• windows10-64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1645495&startday=2020-06-19&endday=2020-06-19&tree=all

Comment 12

[Tom Tung [:tt, :ttung]]

(In reply to Tom Tung [:tt, :ttung] from comment #10)

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

There is no failure like for the new spilted tests in D80364

Comment 13

[Intermittent Failures Robot]

147 failures in 4035 pushes (0.036 failures/push) were associated with this bug in the last 7 days.

This is the #6 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• try: 21
• autoland: 84
• mozilla-central: 42

Platform breakdown:

• linux1804-64-asan: 1
• linux1804-64: 115
• linux1804-64-ccov: 21
• windows10-64-ccov: 9
• windows10-64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1645495&startday=2020-06-15&endday=2020-06-21&tree=all

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/bf21f044ae70
Split up browser_timing_precision_cross_origin_isolated.js into different tests; r=timhuang

Comment 15

[Natalia Csoregi [:nataliaCs]]

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

Comment 16

[Intermittent Failures Robot]

9 failures in 5252 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• autoland: 3
• mozilla-central: 4
• try: 2

Platform breakdown:

• linux1804-64: 6
• linux1804-64-ccov: 2
• windows10-64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1645495&startday=2020-06-22&endday=2020-06-28&tree=all