1755274 - Intermittent toolkit/components/pictureinpicture/tests/browser_telemetry_togglePiP.js | Test timed out -

Status: RESOLVED FIXED

(Toolkit :: Picture-in-Picture, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-02-14T10:37:47.996Z] 10:37:47     INFO - TEST-START | toolkit/components/pictureinpicture/tests/browser_telemetry_togglePiP.js
[task 2022-02-14T10:38:33.000Z] 10:38:33     INFO - TEST-INFO | started process screentopng
[task 2022-02-14T10:38:33.627Z] 10:38:33     INFO - TEST-INFO | screentopng: exit 0
[task 2022-02-14T10:38:33.628Z] 10:38:33     INFO - Buffered messages logged at 10:37:47
[task 2022-02-14T10:38:33.628Z] 10:38:33     INFO - Entering test bound 
[task 2022-02-14T10:38:33.629Z] 10:38:33     INFO - Buffered messages logged at 10:37:48
[task 2022-02-14T10:38:33.630Z] 10:38:33     INFO - Waiting for videos to be ready
[task 2022-02-14T10:38:33.630Z] 10:38:33     INFO - Waiting for 'canplaythrough' for 'with-controls'
[task 2022-02-14T10:38:33.631Z] 10:38:33     INFO - Buffered messages finished
[task 2022-02-14T10:38:33.632Z] 10:38:33     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/pictureinpicture/tests/browser_telemetry_togglePiP.js | Test timed out - 
[task 2022-02-14T10:38:33.632Z] 10:38:33     INFO - GECKO(17269) | MEMORY STAT | vsize 3814MB | residentFast 358MB | heapAllocated 202MB
[task 2022-02-14T10:38:33.633Z] 10:38:33     INFO - TEST-OK | toolkit/components/pictureinpicture/tests/browser_telemetry_togglePiP.js | took 45009ms
[task 2022-02-14T10:38:33.633Z] 10:38:33     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-02-14T10:38:33.633Z] 10:38:33     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/pictureinpicture/tests/browser_telemetry_togglePiP.js | Found a tab after previous test timed out: http://example.com/browser/toolkit/components/pictureinpicture/tests/test-page.html - 
[task 2022-02-14T10:38:33.633Z] 10:38:33     INFO - checking window state
[task 2022-02-14T10:38:33.634Z] 10:38:33     INFO - TEST-START | toolkit/components/pictureinpicture/tests/browser_text_tracks_webvtt_1.js
[task 2022-02-14T10:38:33.638Z] 10:38:33     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-02-14T10:38:33.639Z] 10:38:33     INFO - Buffered messages logged at 10:38:33
[task 2022-02-14T10:38:33.642Z] 10:38:33     INFO - Entering test bound test_text_tracks_new_window_pref_disabled
[task 2022-02-14T10:38:33.643Z] 10:38:33     INFO - Running test: new window - pref disabled
[task 2022-02-14T10:38:33.643Z] 10:38:33     INFO - Buffered messages finished
[task 2022-02-14T10:38:33.644Z] 10:38:33     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/pictureinpicture/tests/browser_telemetry_togglePiP.js | Uncaught exception received from previously timed out test - AbortError: Actor 'SpecialPowers' destroyed before query 'Spawn' was resolved
[task 2022-02-14T10:38:33.645Z] 10:38:33     INFO - GECKO(17269) | JavaScript error: chrome://mochikit/content/browser-test.js, line 1052: TypeError: can't access property "shift", currentScope.__tasks is null
[task 2022-02-14T10:38:33.645Z] 10:38:33     INFO - Console message: [JavaScript Error: "TypeError: can't access property "shift", currentScope.__tasks is null" {file: "chrome://mochikit/content/browser-test.js" line: 1052}]
[task 2022-02-14T10:38:33.646Z] 10:38:33     INFO - Preparing video and initial text tracks
[task 2022-02-14T10:38:33.646Z] 10:38:33     INFO - Waiting for videos to be ready
[task 2022-02-14T10:38:33.647Z] 10:38:33     INFO - TEST-PASS | toolkit/components/pictureinpicture/tests/browser_text_tracks_webvtt_1.js | Number of tracks loaded should be 5 - 5 == 5 - 

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 3

Platform and build breakdown:

• linux1804-64-qr: 3
  • opt: 1
  • debug: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755274&startday=2022-02-14&endday=2022-02-20&tree=all

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755274&startday=2022-02-28&endday=2022-03-06&tree=all

Comment 3

[Intermittent Failures Robot]

17 failures in 3304 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 14
• mozilla-central: 3

Platform and build breakdown:

• linux1804-64-qr: 9
  • opt: 7
  • debug: 2
• linux1804-64-asan-qr: 6
  • opt: 6
• linux1804-64-shippable-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755274&startday=2022-03-14&endday=2022-03-20&tree=all

Comment 4

[Intermittent Failures Robot]

20 failures in 756 pushes (0.026 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 16
• mozilla-central: 4

Platform and build breakdown:

• linux1804-64-asan-qr: 8
  • opt: 8
• linux1804-64-shippable-qr: 5
  • opt: 5
• linux1804-64-qr: 7
  • opt: 5
  • debug: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755274&startday=2022-03-22&endday=2022-03-22&tree=all

Comment 5

[Intermittent Failures Robot]

35 failures in 691 pushes (0.051 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 28
• mozilla-central: 6
• try: 1

Platform and build breakdown:

• linux1804-64-qr: 19
  • opt: 12
  • debug: 7
• linux1804-64-shippable-qr: 4
  • opt: 4
• linux1804-64-asan-qr: 12
  • opt: 12

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755274&startday=2022-03-23&endday=2022-03-23&tree=all

Comment 6

[Intermittent Failures Robot]

17 failures in 536 pushes (0.032 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 14
• mozilla-central: 2
• try: 1

Platform and build breakdown:

• linux1804-64-qr: 9
  • opt: 6
  • debug: 3
• linux1804-64-asan-qr: 5
  • opt: 5
• linux1804-64-shippable-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755274&startday=2022-03-25&endday=2022-03-25&tree=all

Comment 7

[Iulian Moraru]

Update:
There have been 117 failures within the last 7 days:
• 36 failures on Linux 18.04 x64 WebRender asan opt
• 21 failures on Linux 18.04 x64 WebRender debug
• 39 failures on Linux 18.04 x64 WebRender opt
• 21 failures on Linux 18.04 x64 WebRender Shippable opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=372504670&repo=autoland&lineNumber=23792

[task 2022-03-27T15:46:49.964Z] 15:46:49     INFO - TEST-START | toolkit/components/pictureinpicture/tests/browser_telemetry_togglePiP.js
[task 2022-03-27T15:46:49.985Z] 15:46:49     INFO - GECKO(7904) | [Child 7995: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7f2d6822b000 == 2 [pid = 7995] [id = 62]
[task 2022-03-27T15:46:49.986Z] 15:46:49     INFO - GECKO(7904) | [Child 7995: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 7 (7f2d734be260) [pid = 7995] [serial = 145] [outer = 0]
[task 2022-03-27T15:46:49.986Z] 15:46:49     INFO - GECKO(7904) | [Child 7995: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 8 (7f2d6822b400) [pid = 7995] [serial = 146] [outer = 7f2d734be260]
[task 2022-03-27T15:46:50.112Z] 15:46:50     INFO - GECKO(7904) | [Child 7995: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 9 (7f2d6822c800) [pid = 7995] [serial = 147] [outer = 7f2d734be260]
[task 2022-03-27T15:46:52.353Z] 15:46:52     INFO - GECKO(7904) | [Parent 7904: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 25 (7fc88de7b7d0) [pid = 7904] [serial = 126] [outer = 0] [url = chrome://browser/content/browser.xhtml]
<...>
[task 2022-03-27T15:47:27.422Z] 15:47:27     INFO - GECKO(7904) | [Child 7995: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (7f2d690b5c00) [pid = 7995] [serial = 74] [outer = 0] [url = http://example.com/browser/toolkit/components/pictureinpicture/tests/test-media-stream.html]
[task 2022-03-27T15:48:19.973Z] 15:48:19     INFO - TEST-INFO | started process screentopng
[task 2022-03-27T15:48:20.385Z] 15:48:20     INFO - TEST-INFO | screentopng: exit 0
[task 2022-03-27T15:48:20.385Z] 15:48:20     INFO - Buffered messages logged at 15:46:49
[task 2022-03-27T15:48:20.385Z] 15:48:20     INFO - Entering test bound 
[task 2022-03-27T15:48:20.386Z] 15:48:20     INFO - Buffered messages logged at 15:46:50
[task 2022-03-27T15:48:20.386Z] 15:48:20     INFO - Waiting for videos to be ready
[task 2022-03-27T15:48:20.386Z] 15:48:20     INFO - Waiting for 'canplaythrough' for 'no-controls'
[task 2022-03-27T15:48:20.386Z] 15:48:20     INFO - Buffered messages finished
[task 2022-03-27T15:48:20.386Z] 15:48:20     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/pictureinpicture/tests/browser_telemetry_togglePiP.js | Test timed out - 
[task 2022-03-27T15:48:20.386Z] 15:48:20     INFO - GECKO(7904) | MEMORY STAT | vsize 3854MB | residentFast 478MB | heapAllocated 207MB
[task 2022-03-27T15:48:20.386Z] 15:48:20     INFO - TEST-OK | toolkit/components/pictureinpicture/tests/browser_telemetry_togglePiP.js | took 90020ms
[task 2022-03-27T15:48:20.386Z] 15:48:20     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-03-27T15:48:20.387Z] 15:48:20     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/pictureinpicture/tests/browser_telemetry_togglePiP.js | Found a tab after previous test timed out: http://example.com/browser/toolkit/components/pictureinpicture/tests/test-page.html - 
[task 2022-03-27T15:48:20.388Z] 15:48:20     INFO - GECKO(7904) | [Child 8110: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7fcf3af32400 == 1 [pid = 8110] [id = 76]
[task 2022-03-27T15:48:20.389Z] 15:48:20     INFO - GECKO(7904) | [Child 8110: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (7fcf3bef5260) [pid = 8110] [serial = 175] [outer = 0]
[task 2022-03-27T15:48:20.390Z] 15:48:20     INFO - GECKO(7904) | [Child 8110: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (7fcf3af32800) [pid = 8110] [serial = 176] [outer = 7fcf3bef5260]
[task 2022-03-27T15:48:20.390Z] 15:48:20     INFO - checking window state
[task 2022-03-27T15:48:20.391Z] 15:48:20     INFO - TEST-START | toolkit/components/pictureinpicture/tests/browser_text_tracks_webvtt_1.js

Comment 8

[Iulian Moraru]

Hi Mike! Can you please take a look at this? Maybe you could help us assign it to someone.
Thank you!

Comment 9

[Iulian Moraru]

Could the spike in failure rate be caused by Bug 1757927?

Comment 10

[Intermittent Failures Robot]

118 failures in 3341 pushes (0.035 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:

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

Platform and build breakdown:

• linux1804-64-qr: 61
  • debug: 20
  • opt: 41
• linux1804-64-shippable-qr: 22
  • opt: 22
• linux1804-64-asan-qr: 35
  • opt: 35

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755274&startday=2022-03-21&endday=2022-03-27&tree=all

Comment 11

[Intermittent Failures Robot]

16 failures in 517 pushes (0.031 failures/push) were associated with this bug yesterday.

** 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: 16

Platform and build breakdown:

• linux1804-64-qr: 9
  • opt: 6
  • debug: 3
• linux1804-64-asan-qr: 6
  • opt: 6
• linux1804-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755274&startday=2022-03-28&endday=2022-03-28&tree=all

Comment 12

[kpatenio]

I can investigate the test failures here

Comment 13

[Andreea Pavel [:apavel]]

Attachment: Bug 1755274 - disable browser_telemetry_togglePiP.js on linux64 opt r?#intermittent-reviewers

Comment 14

[Intermittent Failures Robot]

24 failures in 680 pushes (0.035 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 22
• try: 1
• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-qr: 15
  • opt: 13
  • debug: 2
• linux1804-64-asan-qr: 6
  • opt: 6
• linux1804-64-shippable-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755274&startday=2022-03-29&endday=2022-03-29&tree=all

Comment 15

[Andreea Pavel [:apavel]]

@kpatenio: Test got disabled to reduce in-tree noise. Please re-enable it in the fix.
Thank you.

Comment 16

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/a63d935a13b9
disable browser_telemetry_togglePiP.js on linux64 opt r=aryx DONTBUILD

Comment 17

[Narcis Beleuzu [:NarcisB]]

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

Comment 18

[kpatenio]

Here are my observations so far. Two pip-related bug fixes were merged around the same time the spike in failures occurred:

1. Bug 1757927
2. Bug 1757921

There is also this third bug fix that followed after option 2 (since it was dependent on it):

3. Bug 1759603

I think the failure is coming from this waitForEvent() that never resolves. Option 1 relies on picture in picture being enabled via the pip toggle or context menu. On the other hand, the failure occurs while waiting for the video source to load - even before we enable picture in picture.

Among the first two bugs, I feel option 2 is likely to cause problems with the test. Bug 1757921 slightly modifies how we show/hide the pip toggle on a video element by adding the ability to modify that behaviour with a video wrapper, and it is possible that it is affecting how the video is loaded. (Although, it is still not clear to me why). While option 3 was merged more recently, option 3 has very minimal changes; it merely builds upon option 2 and does not even modify PictureInPictureChild.jsm.

I ran try pushes for linux x64 to see if commenting out any of the first two bug changes reduced intermittence, and it seems commenting out option 2 helps a bit. (Commenting out option 1 resulted in causing more failures for this test).

Comment 19

[Intermittent Failures Robot]

60 failures in 3323 pushes (0.018 failures/push) were associated with this bug in the last 7 days.

This is the #12 most frequent failure this week.

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

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

Repository breakdown:

• autoland: 52
• try: 1
• mozilla-central: 7

Platform and build breakdown:

• linux1804-64-qr: 38
  • opt: 21
  • debug: 17
• linux1804-64-asan-qr: 17
  • opt: 17
• linux1804-64-shippable-qr: 5
  • opt: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755274&startday=2022-03-28&endday=2022-04-03&tree=all

Comment 20

[Atila Butkovits]

Attachment: Bug 1755274 - disable browser_telemetry_togglePiP.js on Linux_64_Nofis_debug for frequent failures. r=#intermittent-reviewers

Comment 21

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/bfa3af44ba5f
disable browser_telemetry_togglePiP.js on Linux_64_Nofis_debug for frequent failures. r=intermittent-reviewers,pip-reviewers,jmaher,mconley

Comment 22

[Norisz Fay [:noriszfay]]

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

Comment 23

[Intermittent Failures Robot]

16 failures in 2922 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 10
• mozilla-central: 5
• try: 1

Platform and build breakdown:

• linux1804-64-qr: 16
  • debug: 16

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755274&startday=2022-04-04&endday=2022-04-10&tree=all

Comment 24

[kpatenio]

Attachment: Bug 1755274 - adjust test order in browser.ini to reduce browser_telemetry_togglePiP.js intermittence. r=#pip-reviewers!

Comment 25

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/27f4c9e3ab52
adjust test order in browser.ini to reduce browser_telemetry_togglePiP.js intermittence. r=pip-reviewers,mhowell

Comment 26

[Cristina Cozmuta (:CrissCozmuta)]

https://hg.mozilla.org/mozilla-central/rev/27f4c9e3ab52