1863408 - Perma wmfme [tier 2] dom/media/mediasource/test/test_AVC3_mp4.html | Test timed out. -

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

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

---

[task 2023-11-06T15:39:47.487Z] 15:39:47     INFO - TEST-PASS | dom/media/mediasource/test/test_AVC3_mp4.html | fetchWithXHR load uri='avc3/init.mp4' status=200 
[task 2023-11-06T15:39:47.488Z] 15:39:47     INFO - Loading buffer: [0, 687)
[task 2023-11-06T15:39:47.488Z] 15:39:47     INFO - Buffered messages finished
[task 2023-11-06T15:39:47.488Z] 15:39:47     INFO - TEST-UNEXPECTED-FAIL | dom/media/mediasource/test/test_AVC3_mp4.html | Test timed out. - 
[task 2023-11-06T15:39:48.406Z] 15:39:48     INFO - GECKO(5176) | MEMORY STAT heapAllocated not supported in this build configuration.
[task 2023-11-06T15:39:48.407Z] 15:39:48     INFO - GECKO(5176) | MEMORY STAT | vsize 19405604MB | vsizeMaxContiguous 81058610MB | residentFast 220MB
[task 2023-11-06T15:39:48.524Z] 15:39:48     INFO - TEST-OK | dom/media/mediasource/test/test_AVC3_mp4.html | took 305003ms
[task 2023-11-06T15:39:48.662Z] 15:39:48     INFO - TEST-START | dom/media/mediasource/test/test_AbortAfterPartialMediaSegment.html
[task 2023-11-06T15:40:30.374Z] 15:40:30     INFO -  console.error: (new TypeError("connection not specified or invalid.", "resource://gre/modules/Sqlite.sys.mjs", 1522))
[task 2023-11-06T15:40:30.375Z] 15:40:30     INFO -  console.error: (new TypeError("can't access property \"executeBeforeShutdown\", db is undefined", "resource://gre/modules/PlacesUtils.sys.mjs", 1467))
[task 2023-11-06T15:42:30.375Z] 15:42:30     INFO -  console.error: (new TypeError("can't access property \"executeTransaction\", db is undefined", "resource://gre/modules/PlacesFrecencyRecalculator.sys.mjs", 171))
[task 2023-11-06T15:45:17.409Z] 15:45:17     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-11-06T15:45:17.410Z] 15:45:17     INFO - Buffered messages logged at 15:39:49
[task 2023-11-06T15:45:17.410Z] 15:45:17     INFO - TEST-PASS | dom/media/mediasource/test/test_AbortAfterPartialMediaSegment.html | fetchWithXHR load uri='1516754.webm' status=200 
[task 2023-11-06T15:45:17.411Z] 15:45:17     INFO - - append init segment, a media segment and a partial media segment header -
[task 2023-11-06T15:45:17.411Z] 15:45:17     INFO - - wait for updateend -
[task 2023-11-06T15:45:17.411Z] 15:45:17     INFO - Buffered messages finished
[task 2023-11-06T15:45:17.412Z] 15:45:17     INFO - TEST-UNEXPECTED-FAIL | dom/media/mediasource/test/test_AbortAfterPartialMediaSegment.html | Test timed out. - 
[task 2023-11-06T15:45:18.440Z] 15:45:18     INFO - GECKO(5176) | MEMORY STAT | vsize 19405611MB | vsizeMaxContiguous 81058610MB | residentFast 223MB
[task 2023-11-06T15:45:18.454Z] 15:45:18     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-11-06T15:45:18.454Z] 15:45:18     INFO - TEST-UNEXPECTED-FAIL | dom/media/mediasource/test/test_AbortAfterPartialMediaSegment.html |  failed with error InvalidStateError 
[task 2023-11-06T15:45:18.454Z] 15:45:18     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:426:16
[task 2023-11-06T15:45:18.455Z] 15:45:18     INFO -     runWithMSE@dom/media/mediasource/test/mediasource.js:33:7
[task 2023-11-06T15:45:18.455Z] 15:45:18     INFO -     async*@dom/media/mediasource/test/test_AbortAfterPartialMediaSegment.html:22:11
[task 2023-11-06T15:45:18.464Z] 15:45:18     INFO - GECKO(5176) | JavaScript error: http://mochi.test:8888/tests/dom/media/mediasource/test/test_AbortAfterPartialMediaSegment.html, line 47: InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable
[task 2023-11-06T15:45:18.524Z] 15:45:18    ERROR - TEST-UNEXPECTED-FAIL | /tests/dom/media/mediasource/test/test_AbortAfterPartialMediaSegment.html logged result after SimpleTest.finish():  failed with error InvalidStateError
[task 2023-11-06T15:45:18.562Z] 15:45:18     INFO - TEST-OK | dom/media/mediasource/test/test_AbortAfterPartialMediaSegment.html | took 329900ms
[task 2023-11-06T15:45:18.694Z] 15:45:18     INFO - TEST-START | dom/media/mediasource/test/test_AppendPartialInitSegment.html
[task 2023-11-06T15:50:47.457Z] 15:50:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-11-06T15:50:47.458Z] 15:50:47     INFO - Buffered messages logged at 15:45:19
[task 2023-11-06T15:50:47.459Z] 15:50:47     INFO - TEST-PASS | dom/media/mediasource/test/test_AppendPartialInitSegment.html | fetchWithXHR load uri='seek.webm' status=200 
[task 2023-11-06T15:50:47.459Z] 15:50:47     INFO - - append partial init segment -
[task 2023-11-06T15:50:47.460Z] 15:50:47     INFO - - wait for updateend -
[task 2023-11-06T15:50:47.460Z] 15:50:47     INFO - - append remaining init segment -
[task 2023-11-06T15:50:47.461Z] 15:50:47     INFO - - wait for metadata -
[task 2023-11-06T15:50:47.461Z] 15:50:47     INFO - Buffered messages finished
[task 2023-11-06T15:50:47.462Z] 15:50:47     INFO - TEST-UNEXPECTED-FAIL | dom/media/mediasource/test/test_AppendPartialInitSegment.html | Test timed out. - 
[task 2023-11-06T15:50:48.488Z] 15:50:48     INFO - GECKO(5176) | MEMORY STAT | vsize 19405609MB | vsizeMaxContiguous 81058610MB | residentFast 249MB
[task 2023-11-06T15:50:48.596Z] 15:50:48     INFO - TEST-OK | dom/media/mediasource/test/test_AppendPartialInitSegment.html | took 329903ms
[task 2023-11-06T15:50:48.713Z] 15:50:48     INFO - TEST-START | dom/media/mediasource/test/test_AudioChange_mp4.html
[task 2023-11-06T15:50:49.037Z] 15:50:49     INFO - GECKO(5176) | JavaScript error: resource://gre/modules/XULStore.sys.mjs, line 60: Error: Can't find profile directory.
[task 2023-11-06T15:50:49.045Z] 15:50:49     INFO - GECKO(5176) | JavaScript error: resource://gre/modules/XULStore.sys.mjs, line 60: Error: Can't find profile directory.
[task 2023-11-06T15:50:49.051Z] 15:50:49     INFO - GECKO(5176) | JavaScript error: resource://gre/modules/XULStore.sys.mjs, line 60: Error: Can't find profile directory.
[task 2023-11-06T15:50:49.056Z] 15:50:49     INFO - GECKO(5176) | JavaScript error: resource://gre/modules/XULStore.sys.mjs, line 60: Error: Can't find profile directory.
[task 2023-11-06T15:50:49.060Z] 15:50:49     INFO - GECKO(5176) | JavaScript error: resource://gre/modules/XULStore.sys.mjs, line 60: Error: Can't find profile directory.
[task 2023-11-06T15:55:48.994Z] 15:55:48     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-11-06T15:55:48.995Z] 15:55:48     INFO - Buffered messages logged at 15:50:49
[task 2023-11-06T15:55:48.995Z] 15:55:48     INFO - TEST-PASS | dom/media/mediasource/test/test_AudioChange_mp4.html | Receive a sourceopen event 
[task 2023-11-06T15:55:48.996Z] 15:55:48     INFO - TEST-PASS | dom/media/mediasource/test/test_AudioChange_mp4.html | readyState is HAVE_NOTHING 
[task 2023-11-06T15:55:48.996Z] 15:55:48     INFO - TEST-PASS | dom/media/mediasource/test/test_AudioChange_mp4.html | fetchWithXHR load uri='aac20-48000-64000-init.mp4' status=200 
[task 2023-11-06T15:55:48.997Z] 15:55:48     INFO - Loading buffer: [0, 1246)
[task 2023-11-06T15:55:48.997Z] 15:55:48     INFO - Buffered messages finished
[task 2023-11-06T15:55:48.998Z] 15:55:48     INFO - TEST-UNEXPECTED-FAIL | dom/media/mediasource/test/test_AudioChange_mp4.html | Test timed out. - 
[task 2023-11-06T15:55:48.998Z] 15:55:48     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-11-06T15:55:48.998Z] 15:55:48     INFO - TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up. - 
[task 2023-11-06T15:55:48.999Z] 15:55:48     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-11-06T15:55:48.999Z] 15:55:48     INFO - TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 45 remaining tests. - 
[task 2023-11-06T15:55:50.030Z] 15:55:50     INFO - GECKO(5176) | MEMORY STAT | vsize 19405616MB | vsizeMaxContiguous 81058610MB | residentFast 286MB
[task 2023-11-06T15:55:50.040Z] 15:55:50     INFO - got abort event
[task 2023-11-06T15:55:50.042Z] 15:55:50     INFO - got emptied event
[task 2023-11-06T15:55:50.084Z] 15:55:50     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-11-06T15:55:50.085Z] 15:55:50     INFO - TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | /tests/dom/media/mediasource/test/test_AudioChange_mp4.html - finished in a non-clean fashion, probably because it didn't call SimpleTest.finish()
[task 2023-11-06T15:55:50.085Z] 15:55:50     INFO - {'loaded_test_url': '/tests/dom/media/mediasource/test/test_AudioChange_mp4.html'}
[task 2023-11-06T15:55:50.143Z] 15:55:50     INFO - TEST-UNEXPECTED-ERROR | (SimpleTest/TestRunner.js) | Finished in 301373ms
[task 2023-11-06T15:55:50.144Z] 15:55:50     INFO - {'runtime': '301373'}
[task 2023-11-06T15:55:50.144Z] 15:55:50     INFO - TEST-INFO 
[task 2023-11-06T15:55:50.293Z] 15:55:50     INFO - TEST-START | Shutdown

Comment 1

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

:bobowen, since you are the author of the regressor, bug 1793966, could you take a look?

For more information, please visit BugBot documentation.

Comment 2

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

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

Comment 3

[Bob Owen (:bobowen)]

I'll take a look, my initial thought is that this process should not be being used for other decoders.
alwu: is something running in the WMF CDM process that shouldn't be?

Comment 4

[Bob Owen (:bobowen)]

I'd missed that this is for ASAN builds, so presumably the LPAC is blocking the writing out of the ASAN data, but I wonder how this works for other sandbox processes.

Comment 5

[Bob Owen (:bobowen)]

ASan seems to require quite a lot of access at start-up, which we don't get in the same way with LPAC as with the other sandboxing mechanisms.
So, I think the simplest thing is just to disable the LPAC on ASan builds. It shouldn't affect any of the other code paths in our code.

Comment 6

[Bob Owen (:bobowen)]

Attachment: Bug 1863408: Don't use LPAC for ASan builds. r=handyman!

ASan requires access early in the process, which we don't get with an LPAC.

Comment 7

[Bob Owen (:bobowen)]

decoder - I'm just disabling LPAC for ASan builds here (which effectively removes the sandboxing for this utility process type), let me know if you think this is a longer term issue and I'll file a follow-up to see if I can get it working with the LPAC enabled.

Comment 8

[Intermittent Failures Robot]

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

This is the #24 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: 47
• mozilla-central: 13

Platform and build breakdown:

• windows11-64-2009-asan-qr: 60
  • opt: 60

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1863408&startday=2023-11-06&endday=2023-11-12&tree=all

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/0ba3f1bfcc12
Don't use LPAC for ASan builds. r=handyman

Comment 10

[Serban Stanca [:SerbanS]]

https://hg.mozilla.org/mozilla-central/rev/0ba3f1bfcc12

Comment 11

[Intermittent Failures Robot]

22 failures in 3495 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 16
• mozilla-central: 6

Platform and build breakdown:

• windows11-64-2009-asan-qr: 21
  • opt: 21
• windows11-64-2009-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1863408&startday=2023-11-13&endday=2023-11-19&tree=all

Comment 12

[Christian Holler (:decoder)]

(In reply to Bob Owen (:bobowen) from comment #7)

decoder - I'm just disabling LPAC for ASan builds here (which effectively removes the sandboxing for this utility process type), let me know if you think this is a longer term issue and I'll file a follow-up to see if I can get it working with the LPAC enabled.

Fwiw, I think this is fine. ASan is a testing-only tool and while we would like to test as closely as possible to what we ship, we shouldn't waste energy on this particular matter.

Comment 13

[:gerard-majax]

Bob, could this be a dupe of bug 1781570 ?

Comment 14

[Bob Owen (:bobowen)]

(In reply to :gerard-majax from comment #13)

Bob, could this be a dupe of bug 1781570 ?

This was caused by the LPAC, so I don't think it could be a direct duplicate.
I guess that it might be that the other one is/was also caused by something that is in force from the beginning of the sandboxed process and interferes with Asan.