1568176 - Intermittent PID 12200 | Assertion failure: NS_IsMainThread(), at z:/build/build/src/toolkit/crashreporter/nsExceptionHandler.cpp:2107 after test_multiple_mediastreamtracks.html or other mediastream tests

Status: RESOLVED DUPLICATE of bug 1577534

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

Description

[Treeherder Bug Filer]

Filed by: nerli [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=257848959&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/C9tHLiDbS06SR4dHVIwtyg/runs/0/artifacts/public/logs/live_backing.log

---

10:58:58 INFO - PID 12200 | [Parent 12200, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
10:58:58 INFO - PID 12200 | [Child 7604, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
10:58:58 INFO - PID 12200 | [Parent 12200, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
10:58:58 INFO - PID 12200 | [GPU 12236, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
10:58:58 INFO - PID 12200 | [GPU 12236, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/c
10:58:58 INFO - PID 12200 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
10:58:58 INFO - PID 12200 | ommon/ipc_channel_win.cc, line 341
10:58:58 INFO - PID 12200 | [GPU 12236, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
10:58:58 INFO - PID 12200 | [GPU 12236, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
10:58:58 INFO - PID 12200 | [Parent 12200, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
10:58:58 INFO - PID 12200 | [Child 7604, ProcessHangMon] WARNING: failed to create pipe: 2: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 227
10:58:58 INFO - PID 12200 | [Child 7604, Chrome_ChildThread] ###!!! ASSERTION: Failed Dispatch after xpcom-shutdown-threads: 'false', file z:/build/build/src/xpcom/threads/ThreadEventTarget.cpp, line 117
10:58:58 INFO - PID 12200 | Assertion failure: NS_IsMainThread(), at z:/build/build/src/toolkit/crashreporter/nsExceptionHandler.cpp:2107
10:58:58 INFO - PID 12200 | ### ERROR: SymInitialize: The parameter is incorrect.
10:58:58 INFO - PID 12200 | #01: ??? (???:???)
10:58:58 INFO - PID 12200 | ### ERROR: SymInitialize: The parameter is incorrect.
10:58:58 INFO - PID 12200 | #02: ??? (???:???)
10:58:58 INFO - PID 12200 | ### ERROR: SymInitialize: The parameter is incorrect.
10:58:58 INFO - PID 12200 | #03: ??? (???:???)
10:58:58 INFO - PID 12200 | ### ERROR: SymInitialize: The parameter is incorrect.
10:58:58 INFO - PID 12200 | #04: ??? (???:???)
10:58:58 INFO - PID 12200 | ### ERROR: SymInitialize: The parameter is incorrect.
10:58:58 INFO - PID 12200 | #05: ??? (???:???)
10:58:58 INFO - PID 12200 | ### ERROR: SymInitialize: The parameter is incorrect.
10:58:58 INFO - PID 12200 | #06: ??? (???:???)
10:58:58 INFO - PID 12200 | ### ERROR: SymInitialize: The parameter is incorrect.
10:58:58 INFO - PID 12200 | #07: ??? (???:???)
10:58:58 INFO - PID 12200 | ### ERROR: SymInitialize: The parameter is incorrect.
10:58:58 INFO - PID 12200 | #08: ??? (???:???)
10:58:58 INFO - PID 12200 | ### ERROR: SymInitialize: The parameter is incorrect.
10:58:58 INFO - PID 12200 | #09: ??? (???:???)
10:58:59 INFO - TEST-PASS | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_WebExtensionPolicy.js | took 2368ms

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-64: 1

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

Comment 2

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 3

[Andreea Pavel [:apavel]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=264069892&repo=autoland&lineNumber=9547

[task 2019-08-29T15:38:10.315Z] 15:38:10 INFO - TEST-OK | dom/media/test/test_multiple_mediastreamtracks.html | took 2367ms
[task 2019-08-29T15:38:10.351Z] 15:38:10 INFO - GECKO(5661) | [Parent 5661, Main Thread] WARNING: Cannot set transparency mode on non-popup windows.: file /builds/worker/workspace/build/src/widget/gtk/nsWindow.cpp, line 4457
[task 2019-08-29T15:38:10.367Z] 15:38:10 INFO - GECKO(5661) | ++DOMWINDOW == 20 (0x7f39bbe70800) [pid = 5739] [serial = 116] [outer = 0x7f39bcb84e20]
[task 2019-08-29T15:38:10.402Z] 15:38:10 INFO - GECKO(5661) | [GPU 5691, Compositor] WARNING: Possibly dropping task posted to updater thread: file /builds/worker/workspace/build/src/gfx/layers/apz/src/APZUpdater.cpp, line 429
[task 2019-08-29T15:38:10.454Z] 15:38:10 INFO - TEST-START | Shutdown

[task 2019-08-29T15:38:11.888Z] 15:38:11 INFO - GECKO(5661) | nsStringStats
[task 2019-08-29T15:38:11.889Z] 15:38:11 INFO - GECKO(5661) | => mAllocCount: 2891
[task 2019-08-29T15:38:11.889Z] 15:38:11 INFO - GECKO(5661) | => mReallocCount: 0
[task 2019-08-29T15:38:11.889Z] 15:38:11 INFO - GECKO(5661) | => mFreeCount: 2891
[task 2019-08-29T15:38:11.889Z] 15:38:11 INFO - GECKO(5661) | => mShareCount: 4304
[task 2019-08-29T15:38:11.889Z] 15:38:11 INFO - GECKO(5661) | => mAdoptCount: 0
[task 2019-08-29T15:38:11.890Z] 15:38:11 INFO - GECKO(5661) | => mAdoptFreeCount: 0
[task 2019-08-29T15:38:11.890Z] 15:38:11 INFO - GECKO(5661) | => Process ID: 5691, Thread ID: 140712789546816
[task 2019-08-29T15:38:12.471Z] 15:38:12 INFO - GECKO(5661) | Assertion failure: NS_IsMainThread(), at /builds/worker/workspace/build/src/toolkit/crashreporter/nsExceptionHandler.cpp:2105
[task 2019-08-29T15:38:33.031Z] 15:38:33 INFO - GECKO(5661) | #01: CrashStatsLogForwarder::UpdateCrashReport() [gfx/thebes/gfxPlatform.cpp:305]
[task 2019-08-29T15:38:33.031Z] 15:38:33 INFO -
[task 2019-08-29T15:38:33.031Z] 15:38:33 INFO - GECKO(5661) | #02: CrashStatsLogForwarder::Log(std::string const&) [gfx/thebes/gfxPlatform.cpp:348]
[task 2019-08-29T15:38:33.033Z] 15:38:33 INFO -
[task 2019-08-29T15:38:33.033Z] 15:38:33 INFO - GECKO(5661) | #03: mozilla::gfx::CriticalLogger::OutputMessage(std::string const&, int, bool) [gfx/2d/Factory.cpp:1125]
[task 2019-08-29T15:38:33.033Z] 15:38:33 INFO -
[task 2019-08-29T15:38:33.034Z] 15:38:33 INFO - GECKO(5661) | #04: mozilla::gfx::Log<1, mozilla::gfx::CriticalLogger>::WriteLog(std::string const&) [gfx/2d/Logging.h:739]
[task 2019-08-29T15:38:33.034Z] 15:38:33 INFO -
[task 2019-08-29T15:38:33.034Z] 15:38:33 INFO - GECKO(5661) | #05: mozilla::gfx::Log<1, mozilla::gfx::CriticalLogger>::Flush() [gfx/2d/Logging.h:281]

Comment 4

[Andreea Pavel [:apavel]]

Andreas can this be from bug 1574965?

There are 14 total failures since August 29th.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=264396980&repo=mozilla-central&lineNumber=51310

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 11
• mozilla-central: 3
• try: 1
• mozilla-inbound: 1

Platform breakdown:

• linux64-qr: 2
• macosx1014-64: 7
• linux64: 7

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1568176&startday=2019-08-26&endday=2019-09-01&tree=all

Comment 6

[Andreas Pehrson [:pehrsons]]

This is indeed from bug 1574965. The root cause of this assertion failure is the same as bug 1577534, and will be fixed there.

But that it requires main thread once it's triggered seems unexpected.

nical, with TextureClient having an atomic refcount, and considering comments like this, it seems to me that it is expected to be released on any thread. Can you take a look at this main thread assert?

Comment 7

[Nicolas Silva [:nical]]

The issue happens in the critical log glue. CrashStatsLogForwarder::Log looks at whether we are on the main thread and if not fowards the log to the main thread for processing. The issue here is that this log is processed after the shutdown of xpcom threads, and at this point anything thread-related tends to produce nonsense (including querying wehether we are on the main thread, even if indeed we are on said main thread).

So this should be fixed by making sure whatever is holding on a graphics resource alive past graphics shutdown (which happens before xpcom-threads shutdown) is released before the graphics shutdown.

In addition we could have some kind of global atomic that is set to false upon xpcom-threads shutdown and queried in the CrashStatsLogForwarder glue to just drop the log in the unfortunate event that a critical log is generated in the late shutdown stage. But if this is coming from a gfx resource held alive this late, it's likely that another assert or crash will come from that too, so the band aid in CrashStatsLogForwarder would probably move the crash somewhere else.

Comment 8

[Andreas Pehrson [:pehrsons]]

Thanks. Let's make this track bug 1577534.

Comment 10

[Intermittent Failures Robot]

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

Repository breakdown:

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

Platform breakdown:

• macosx1014-64: 1
• linux64: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1568176&startday=2019-09-02&endday=2019-09-08&tree=all