Closed Bug 1682123 Opened 5 years ago Closed 4 years ago

Intermittent dom/media/mediacontrol/tests/browser/browser_nosrc_and_error_media.js | Test timed out -

Categories

(Core :: Audio/Video, defect, P5)

Product:
Core
Component:
Audio/Video
Type:
defect

Tracking

()

Status:
RESOLVED WORKSFORME

People

(Reporter: intermittent-bug-filer, Assigned: alwu)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell unknown])

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

[task 2020-12-12T11:16:50.173Z] 11:16:50     INFO - TEST-START | dom/media/mediacontrol/tests/browser/browser_nosrc_and_error_media.js
[task 2020-12-12T11:16:50.937Z] 11:16:50     INFO - GECKO(16629) | [Child 20253, MediaDecoderStateMachine #1] WARNING: Decoder=7f484100f400 state=DECODING_METADATA Decode metadata failed, shutting down decoder: file /builds/worker/checkouts/gecko/dom/media/MediaDecoderStateMachine.cpp:368
[task 2020-12-12T11:16:50.938Z] 11:16:50     INFO - GECKO(16629) | [Child 20253, MediaDecoderStateMachine #1] WARNING: Decoder=7f484100f400 Decode error: NS_ERROR_DOM_MEDIA_METADATA_ERR (0x806e0006): file /builds/worker/checkouts/gecko/dom/media/MediaDecoderStateMachine.cpp:3465
[task 2020-12-12T11:16:51.583Z] 11:16:51     INFO - GECKO(16629) | JavaScript error: resource:///actors/DOMFullscreenParent.jsm, line 130: Error: TelemetryStopwatch: key "FULLSCREEN_CHANGE_MS" was already initialized
[task 2020-12-12T11:16:51.625Z] 11:16:51     INFO - GECKO(16629) | JavaScript error: resource:///actors/DOMFullscreenParent.jsm, line 100: Error: TelemetryStopwatch: finishing nonexisting stopwatch. Histogram: "FULLSCREEN_CHANGE_MS", key: ""
[task 2020-12-12T11:17:35.187Z] 11:17:35     INFO - TEST-INFO | started process screentopng
[task 2020-12-12T11:17:35.656Z] 11:17:35     INFO - TEST-INFO | screentopng: exit 0
[task 2020-12-12T11:17:35.657Z] 11:17:35     INFO - Buffered messages logged at 11:16:50
[task 2020-12-12T11:17:35.657Z] 11:17:35     INFO - Entering test bound setupTestingPref
[task 2020-12-12T11:17:35.658Z] 11:17:35     INFO - Leaving test bound setupTestingPref
[task 2020-12-12T11:17:35.658Z] 11:17:35     INFO - Entering test bound testNoSrcOrErrorMediaEntersPIPMode
[task 2020-12-12T11:17:35.659Z] 11:17:35     INFO - open media page https://example.com/browser/dom/media/mediacontrol/tests/browser/file_no_src_media.html
[task 2020-12-12T11:17:35.660Z] 11:17:35     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "https://example.com/browser/dom/media/mediacontrol/tests/browser/file_no_src_media.html" line: 0}]
[task 2020-12-12T11:17:35.661Z] 11:17:35     INFO - controller should always inactive
[task 2020-12-12T11:17:35.661Z] 11:17:35     INFO - enter PIP mode which would not affect controller
[task 2020-12-12T11:17:35.661Z] 11:17:35     INFO - must wait for focus
[task 2020-12-12T11:17:35.662Z] 11:17:35     INFO - leave PIP mode
[task 2020-12-12T11:17:35.662Z] 11:17:35     INFO - TEST-PASS | dom/media/mediacontrol/tests/browser/browser_nosrc_and_error_media.js | Should be able to find Picture-in-Picture overlay. - {} == true - 
[task 2020-12-12T11:17:35.664Z] 11:17:35     INFO - TEST-PASS | dom/media/mediacontrol/tests/browser/browser_nosrc_and_error_media.js | Video should be showing the expected state. - true == true - 
[task 2020-12-12T11:17:35.664Z] 11:17:35     INFO - TEST-PASS | dom/media/mediacontrol/tests/browser/browser_nosrc_and_error_media.js | controller is still inactive - 
[task 2020-12-12T11:17:35.664Z] 11:17:35     INFO - remove tab
[task 2020-12-12T11:17:35.665Z] 11:17:35     INFO - wait until finishing close tab wrapper
[task 2020-12-12T11:17:35.665Z] 11:17:35     INFO - open media page https://example.com/browser/dom/media/mediacontrol/tests/browser/file_error_media.html
[task 2020-12-12T11:17:35.667Z] 11:17:35     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "https://example.com/browser/dom/media/mediacontrol/tests/browser/file_error_media.html" line: 0}]
[task 2020-12-12T11:17:35.675Z] 11:17:35     INFO - Console message: [JavaScript Warning: "Media resource https://example.com/browser/dom/media/mediacontrol/tests/browser/bogus.ogv could not be decoded." {file: "https://example.com/browser/dom/media/mediacontrol/tests/browser/file_error_media.html" line: 0}]
[task 2020-12-12T11:17:35.675Z] 11:17:35     INFO - controller should always inactive
[task 2020-12-12T11:17:35.675Z] 11:17:35     INFO - enter PIP mode which would not affect controller
[task 2020-12-12T11:17:35.675Z] 11:17:35     INFO - Buffered messages logged at 11:16:51
[task 2020-12-12T11:17:35.676Z] 11:17:35     INFO - must wait for focus
[task 2020-12-12T11:17:35.676Z] 11:17:35     INFO - leave PIP mode
[task 2020-12-12T11:17:35.676Z] 11:17:35     INFO - TEST-PASS | dom/media/mediacontrol/tests/browser/browser_nosrc_and_error_media.js | Should be able to find Picture-in-Picture overlay. - {} == true - 
[task 2020-12-12T11:17:35.677Z] 11:17:35     INFO - TEST-PASS | dom/media/mediacontrol/tests/browser/browser_nosrc_and_error_media.js | Video should be showing the expected state. - true == true - 
[task 2020-12-12T11:17:35.677Z] 11:17:35     INFO - TEST-PASS | dom/media/mediacontrol/tests/browser/browser_nosrc_and_error_media.js | controller is still inactive - 
[task 2020-12-12T11:17:35.678Z] 11:17:35     INFO - remove tab
[task 2020-12-12T11:17:35.679Z] 11:17:35     INFO - wait until finishing close tab wrapper
[task 2020-12-12T11:17:35.681Z] 11:17:35     INFO - Leaving test bound testNoSrcOrErrorMediaEntersPIPMode
[task 2020-12-12T11:17:35.681Z] 11:17:35     INFO - Entering test bound testNoSrcOrErrorMediaEntersFullscreen
[task 2020-12-12T11:17:35.682Z] 11:17:35     INFO - open media page https://example.com/browser/dom/media/mediacontrol/tests/browser/file_no_src_media.html
[task 2020-12-12T11:17:35.682Z] 11:17:35     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "https://example.com/browser/dom/media/mediacontrol/tests/browser/file_no_src_media.html" line: 0}]
[task 2020-12-12T11:17:35.683Z] 11:17:35     INFO - controller should always inactive
[task 2020-12-12T11:17:35.683Z] 11:17:35     INFO - enter and leave fullscreen which would not affect controller[task 2020-12-12T11:17:35.684Z] 11:17:35     INFO - must wait for focus
[task 2020-12-12T11:17:35.685Z] 11:17:35     INFO - TEST-PASS | dom/media/mediacontrol/tests/browser/browser_nosrc_and_error_media.js | no fullscreen element - true == true - 
[task 2020-12-12T11:17:35.686Z] 11:17:35     INFO - Console message: [JavaScript Error: "Error: TelemetryStopwatch: key "FULLSCREEN_CHANGE_MS" was already initialized" {file: "resource:///actors/DOMFullscreenParent.jsm" line: 130}]
[task 2020-12-12T11:17:35.687Z] 11:17:35     INFO - handleEvent@resource:///actors/DOMFullscreenParent.jsm:130:28
[task 2020-12-12T11:17:35.687Z] 11:17:35     INFO - receiveMessage@resource:///actors/DOMFullscreenParent.jsm:70:28
[task 2020-12-12T11:17:35.688Z] 11:17:35     INFO - 
[task 2020-12-12T11:17:35.688Z] 11:17:35     INFO - Console message: [JavaScript Error: "Error: TelemetryStopwatch: finishing nonexisting stopwatch. Histogram: "FULLSCREEN_CHANGE_MS", key: """ {file: "resource:///actors/DOMFullscreenParent.jsm" line: 100}]
[task 2020-12-12T11:17:35.689Z] 11:17:35     INFO - receiveMessage@resource:///actors/DOMFullscreenParent.jsm:100:28
[task 2020-12-12T11:17:35.689Z] 11:17:35     INFO - 
[task 2020-12-12T11:17:35.690Z] 11:17:35     INFO - Buffered messages finished
[task 2020-12-12T11:17:35.690Z] 11:17:35     INFO - TEST-UNEXPECTED-FAIL | dom/media/mediacontrol/tests/browser/browser_nosrc_and_error_media.js | Test timed out - ```

There have been 45 failures in the last 7 days: https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2021-01-21&endday=2021-01-28&tree=trunk&bug=1682123

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=328003472&repo=autoland&lineNumber=14798

Bryce, could you assign someone to look into this?

Flags: needinfo?(bvandyk)
Whiteboard: [stockwell needswork:owner]

Alastor, could you please take a look at this?

Flags: needinfo?(bvandyk) → needinfo?(alwu)

From the log, I can't figure our what's happened. I pushed a patch with debug log to see if that can provide more information.

Assignee: nobody → alwu
Flags: needinfo?(alwu)

By checking the log, the timeout happened on second time we try to create a tab.

Entering test bound testNoSrcOrErrorMediaEntersPIPMode
[task 2021-01-29T23:31:35.606Z] 23:31:35     INFO - open media page https://example.com/browser/dom/media/mediacontrol/tests/browser/file_no_src_media.html
[task 2021-01-29T23:31:35.607Z] 23:31:35     INFO - controller should always inactive
[task 2021-01-29T23:31:35.608Z] 23:31:35     INFO - enter PIP mode which would not affect controller
[task 2021-01-29T23:31:35.608Z] 23:31:35     INFO - must wait for focus
[task 2021-01-29T23:31:35.609Z] 23:31:35     INFO - leave PIP mode
[task 2021-01-29T23:31:35.610Z] 23:31:35     INFO - TEST-PASS | dom/media/mediacontrol/tests/browser/browser_nosrc_and_error_media.js | Should be able to find Picture-in-Picture overlay. - {} == true - 
[task 2021-01-29T23:31:35.615Z] 23:31:35     INFO - TEST-PASS | dom/media/mediacontrol/tests/browser/browser_nosrc_and_error_media.js | Video should be showing the expected state. - true == true - 
[task 2021-01-29T23:31:35.617Z] 23:31:35     INFO - TEST-PASS | dom/media/mediacontrol/tests/browser/browser_nosrc_and_error_media.js | controller is still inactive - 
[task 2021-01-29T23:31:35.618Z] 23:31:35     INFO - remove tab
[task 2021-01-29T23:31:35.618Z] 23:31:35     INFO - wait until finishing close tab wrapper
[task 2021-01-29T23:31:35.619Z] 23:31:35     INFO - open media page https://example.com/browser/dom/media/mediacontrol/tests/browser/file_error_media.html
[task 2021-01-29T23:31:35.624Z] 23:31:35     INFO - TEST-UNEXPECTED-FAIL | dom/media/mediacontrol/tests/browser/browser_nosrc_and_error_media.js | Test timed out -

Just checking the log above, it didn't indicate why it would fail. But I noticed this error stack, which indicates the error happened because we can't access property browsingContext. But the tab was created by the BrowserTestUtil here. which should not have a null linkedBrowser.

[task 2021-01-29T23:31:35.634Z] 23:31:35     INFO - TEST-UNEXPECTED-FAIL | dom/media/mediacontrol/tests/browser/browser_nosrc_and_error_media.js | Uncaught exception received from previously timed out test - at chrome://mochitests/content/browser/dom/media/mediacontrol/tests/browser/head.js:22 - TypeError: can't access property "browsingContext", tab.linkedBrowser is null
[task 2021-01-29T23:31:35.635Z] 23:31:35     INFO - Stack trace:
[task 2021-01-29T23:31:35.635Z] 23:31:35     INFO - tabWrapper@chrome://mochitests/content/browser/dom/media/mediacontrol/tests/browser/head.js:22:7
[task 2021-01-29T23:31:35.636Z] 23:31:35     INFO - createLoadedTabWrapper@chrome://mochitests/content/browser/dom/media/mediacontrol/tests/browser/head.js:89:10

Hi, Emilio,
I found an issue where my created tab won't have a correct linkedBrowser, and posted the details on comment14. Do you know why this could happen? Because I assumed that all tabs should have a valid linkedBrowser.
Thank you so much.

Flags: needinfo?(emilio)

I also found this issue on another test failure, where the tab should still be active and the tab.linkedBrowser should exist.

[task 2021-01-30T00:20:53.446Z] 00:20:53     INFO - TEST-UNEXPECTED-FAIL | dom/media/mediacontrol/tests/browser/browser_remove_controllable_media_for_active_controller.js | Uncaught exception received from previously timed out test - at chrome://mochitests/content/browser/dom/media/mediacontrol/tests/browser/browser_remove_controllable_media_for_active_controller.js:102 - TypeError: can't access property "browsingContext", tab.linkedBrowser is null
[task 2021-01-30T00:20:53.446Z] 00:20:53     INFO - Stack trace:
[task 2021-01-30T00:20:53.447Z] 00:20:53     INFO - checkOrWaitControllerBecomesActive@chrome://mochitests/content/browser/dom/media/mediacontrol/tests/browser/browser_remove_controllable_media_for_active_controller.js:102:22
[task 2021-01-30T00:20:53.448Z] 00:20:53     INFO - testControllerWithActiveMediaSessionShouldStillBeActiveWhenNoControllableMediaPresents@chrome://mochitests/content/browser/dom/media/mediacontrol/tests/browser/browser_remove_controllable_media_for_active_controller.js:28:1

linkedbrowser might be null after tab removal: https://searchfox.org/mozilla-central/rev/fd853f4aea89186efdb368e759a71b7a90c2b89c/browser/base/content/tabbrowser.js#3787

Other than that I don't think it should be null. That being said, I'm not the most expert in that code, I'd ask :mconley or :dao to confirm.

But, are you sure that's the issue? If the issue was a missing linkedBrowser you'd throw an exception instantly. Is it possible that this is hanging when accessing the MediaController instead? It seems it can be created lazily, and that does a bunch of locking and so on. That seems more likely to me looking at the code.

Flags: needinfo?(emilio)

As MediaController is guaranteed not-null, and I didn't see following log message, that is why I assume that the test crashed immediately in createLoadedTabWrapper(), where the error shows that the tab.linkedBrowser is null.

In addition, those the cases I mentioned in comment15 & 16, where tabs are just created. So that seems not related with the tab removal.

I will ask them to see if they have any idea, thank you.

Hi, Mike,
I wonder if you know what thing could make that happen, which is a tab that just gets created doesn't have a valid linkedBrowser?
Because by checking the error log, it showed me that sometime I can't access tab.linkedBrowser, and I've posted some analysis and in comment14&18.
Thank you so much.

Flags: needinfo?(mconley)

I'm not saying that MediaController is null. I'm saying that we might get stuck here and never return to the caller. Not sure though.

Oh those codes are non-blocking, they are just used to register the event listeners.

ConnectInternal and co do grab mutex locks and such though, right?

In this situation NO, because those event producers are actually created by its parant class, which means being created at the same time (BTW I know that is a weird design and I will modify that) so those event producer are not producing any event yet, so blocking won't happen.

Status: NEW → RESOLVED
Closed: 4 years ago
Flags: needinfo?(mconley)
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.