1457372 - Intermittent: SUMMARY: AddressSanitizer: heap-use-after-free /builds/worker/workspace/build/src/dom/media/AudioMixer.h:66:22 in FinishMixing

Status: RESOLVED WORKSFORME

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

Description

[Raul Gurzau (:RaulG)]

https://treeherder.mozilla.org/logviewer.html#?job_id=175885418&repo=autoland&lineNumber=10217

[task 2018-04-27T03:06:55.533Z] 03:06:55     INFO - TEST-START | dom/media/tests/mochitest/test_getUserMedia_GC_MediaStream.html
[task 2018-04-27T03:06:55.817Z] 03:06:55     INFO - GECKO(2777) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2018-04-27T03:06:55.819Z] 03:06:55     INFO - GECKO(2777) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2018-04-27T03:06:56.063Z] 03:06:56     INFO - GECKO(2777) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2018-04-27T03:06:56.068Z] 03:06:56     INFO - GECKO(2777) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2018-04-27T03:06:57.340Z] 03:06:57     INFO - GECKO(2777) | MEMORY STAT | vsize 20973572MB | residentFast 828MB
[task 2018-04-27T03:06:57.345Z] 03:06:57     INFO - GECKO(2777) | =================================================================
[task 2018-04-27T03:06:57.347Z] 03:06:57    ERROR - GECKO(2777) | ==2833==ERROR: AddressSanitizer: heap-use-after-free on address 0x611000cd9f40 at pc 0x7f98f620443e bp 0x7f98dba3f470 sp 0x7f98dba3f468

Comment 1

[Andrew McCreight [:mccr8]]

Karl, it looks like you might be investigating crashes with audio mixer stuff, so you might find this ASan report interesting.

Comment 2

[Karl Tomlinson (:karlt)]

Thank you, Andrew.  There is considerably more information in this report.

Comment 3

[Karl Tomlinson (:karlt)]

Attachment: ASAN report from treeherder log viewer

Read of size on AudioIPC1 thread in
AudioMixer::FinishMixing()
https://hg.mozilla.org/integration/autoland/annotate/d52b265b6b52a817374add2c4e927530dab571a6/dom/media/AudioMixer.h#l66

located 64 bytes inside of 216-byte region
freed by CubebOperation thread in
GraphDriver::Release()
https://hg.mozilla.org/integration/autoland/annotate/d52b265b6b52a817374add2c4e927530dab571a6/dom/media/GraphDriver.h#l116
on AsyncCubebOperation::SHUTDOWN in AsyncCubebTask::Run()
https://hg.mozilla.org/integration/autoland/annotate/d52b265b6b52a817374add2c4e927530dab571a6/dom/media/GraphDriver.cpp#l512

previously allocated by AudioIPC0 thread by new AudioCallbackDriver() in
mozilla::MediaStreamGraphImpl::OpenAudioInputImpl()
https://hg.mozilla.org/integration/autoland/annotate/d52b265b6b52a817374add2c4e927530dab571a6/dom/media/MediaStreamGraph.cpp#l831

CubebOperation thread created by T0 under AudioCallbackDriver::Revive()
https://hg.mozilla.org/integration/autoland/annotate/d52b265b6b52a817374add2c4e927530dab571a6/dom/media/GraphDriver.cpp#l796

AudioIPC0 and AudioIPC1 belong to a thread pool of two threads.

Comment 4

[Ryan VanderMeulen [:RyanVM]]

Karl, are you actively working on this?

Comment 5

[Karl Tomlinson (:karlt)]

I'm not actively working on this (beyond occasionally checking things when I'm
looking at related code).

The source of the problem is not clear and so I don't know which code to spend
time checking.  There are few reports from which to establish a pattern.

I am however considering redesigning all the logic involved because JS engine
changes have destroyed my plans for bug 1458448, and so I'll need to do
something different.  If I do change all the logic, then that's not going to
happen overnight, but a small solution is not likely to be found quickly either.

Comment 6

[Ryan VanderMeulen [:RyanVM]]

Doesn't sound like this is going to go anywhere any time soon, so un-tracking. I'd still happily consider a patch for 61 if one were to materialize.

Comment 8

[Paul Adenot (:padenot)]

Alex, can you make sure this is covered by your asserts ?

Comment 9

[Alex Chronopoulos [:achronop]]

My theory is that an AudioCallbackDriver remains in mixer callback list after it has been destructed. The RemoveCallback method [1] is executed from more than one thread, but the flag that controls the removing is not thread safe. I believe for some reason we fail to remove the callback or we remove it in one thread and re-add it on another. 

I will make the flag atomic, and I will reform the way that we add/remove mixer's callback in order to happen on driver's thread or when thread is not running. I will also assert that the callback is removed at AudioCallbackDriver dctor.

I will implement and land those changes in Bug 1460346 (the asserts bug). I will keep that open to report back if the problem is not solve or if the UAF issue has been replaced by an assert hit.

[1] https://searchfox.org/mozilla-central/source/dom/media/GraphDriver.cpp#799

Comment 10

[Karl Tomlinson (:karlt)]

All callers of RemoveCallback() hold mGraphImpl->GetMonitor().

I'm not clear which associated flag you are referencing, but
mShouldFallbackIfError is accessed outside the monitor.

The MSG should not be calling stream_stop() (from any thread), nor any other
cubeb_stream_ methods on the same stream, while in the data_callback.

Do you know of any situations where cubeb or audioipc would report an error
state for a stream while its data_callback is running?

Wouldn't that be a bug in cubeb because "Stream disabled due to error" is
not compatible with a running stream?

Comment 11

[Alex Chronopoulos [:achronop]]

> All callers of RemoveCallback() hold mGraphImpl->GetMonitor().
> 
> I'm not clear which associated flag you are referencing, but
> mShouldFallbackIfError is accessed outside the monitor.

I am talking about `mAddedMixer` [1] flag which is used from RemoveCallback() method. Indeed, RemoveCallback() is called under the monitor, but the `mAddedMixer` flag is touched here [2] without the monitor being locked.

On the top of that I have noticed that we go to drain state here [3], but we don't remove the mixer callback. If GraphDriver shutdowns after that the mixer callback is not removed. An additional weak point is when the mixer callback is removed after a normal stream stop (by calling the cubeb_stream_stop method not due to drain or error).

I have tried to address the issues above on [4]. Feel free to add your name in reviewers and give me your comments.

> The MSG should not be calling stream_stop() (from any thread), nor any other
> cubeb_stream_ methods on the same stream, while in the data_callback.

That would be convenient but how can we guarantee that. They are two different threads and events can happen asynchronously. Do you mean that we need to add some kind of synchronization between the two threads?

> Do you know of any situations where cubeb or audioipc would report an error
> state for a stream while its data_callback is running?
> 
> Wouldn't that be a bug in cubeb because "Stream disabled due to error" is
> not compatible with a running stream?

We can report error state within the cubeb callback. For example in audiounit we do it here [5]. Is that what you mean? In this case we have stopped the stream before reporting the error. Probably I am not answering your question completely, but I am not sure I am understanding fully the bug you are describing.   

[1] https://searchfox.org/mozilla-central/source/dom/media/GraphDriver.h#549
[2] https://searchfox.org/mozilla-central/source/dom/media/GraphDriver.cpp#888
[3] https://searchfox.org/mozilla-central/source/dom/media/GraphDriver.cpp#1001
[4] https://bugzilla.mozilla.org/attachment.cgi?id=8983365
[5] https://searchfox.org/mozilla-central/source/media/libcubeb/src/cubeb_audiounit.cpp#609

Comment 12

[Karl Tomlinson (:karlt)]

(In reply to Alex Chronopoulos [:achronop] from comment #11)
> > All callers of RemoveCallback() hold mGraphImpl->GetMonitor().
> > 
> > I'm not clear which associated flag you are referencing, but
> > mShouldFallbackIfError is accessed outside the monitor.
> 
> I am talking about `mAddedMixer` [1] flag which is used from
> RemoveCallback() method. Indeed, RemoveCallback() is called under the
> monitor, but the `mAddedMixer` flag is touched here [2] without the monitor
> being locked.

Ah, thanks.  The intention is that RemoveCallback() and AddCallback() calls
(and similarly mAddedMixer access) cannot be made by two threads concurrently
because the MSG has just one graph thread at any time.  There are times that
the graph is managed by the main thread (for Revive() calls for example), but
that shouldn't happen while the graph is accessed from another thread.

> On the top of that I have noticed that we go to drain state here [3], but we
> don't remove the mixer callback. If GraphDriver shutdowns after that the
> mixer callback is not removed.

Thanks!  There is potential for a problem there I think.

On Revive(), if switching to another driver, the callback is removed.
https://searchfox.org/mozilla-central/rev/c621276fbdd9591f52009042d959b9e19b66d49f/dom/media/GraphDriver.cpp#786

If not switching, the intention is that the same driver is reused.
If cubeb_stream_init() fails, however, fallback to a system driver occurs
without removing the callback.

A much simpler design would be to remove the callback when signalling
main thread cleanup (as in your patch), and remove the RemoveCallback()
call in Revive().

> An additional weak point is when the mixer
> callback is removed after a normal stream stop (by calling the
> cubeb_stream_stop method not due to drain or error).

I don't think that should happen.

> > The MSG should not be calling stream_stop() (from any thread), nor any other
> > cubeb_stream_ methods on the same stream, while in the data_callback.
> 
> That would be convenient but how can we guarantee that. They are two
> different threads and events can happen asynchronously. Do you mean that we
> need to add some kind of synchronization between the two threads?

The main thread should only be calling stop after the driver has
called SignalMainThreadCleanup().  i.e. when the callback thread has nothing
remaining to do.

> We can report error state within the cubeb callback. For example in
> audiounit we do it here [5]. Is that what you mean? In this case we have
> stopped the stream before reporting the error.

That should be fine because cubeb's data_callback is not running.
i.e. this is the same thread as the data_callback, and so the state_callback
will not execute concurrently with the data_callback.
(It is also important that the data_callback is not called after the
state_callback reports an error, but I don't have reason to suspect that
is happening, apart from this bug indicating that something is not
behaving as expected.)

Comment 13

[Alex Chronopoulos [:achronop]]

A fix for this has been landed with Bug 1460346. Is there a way to check if this issue has appeared again?

Comment 14

[Jason Kratzer [:jkratzer]]

(In reply to Alex Chronopoulos [:achronop] from comment #13)
> A fix for this has been landed with Bug 1460346. Is there a way to check if
> this issue has appeared again?

I have not seen this issue since I initially reported it via bug 1460865.

Comment 15

[Karl Tomlinson (:karlt)]

The crash report data for bug 1415755, once the fix reaches beta, may be the best indication we have.

Comment 16

[Nils Ohlmeier [:drno]]

So we are waiting for bug 1415755 which itself wait for Bug 1460346 in 63 get into Beta or Release.

Comment 17

[Nils Ohlmeier [:drno]]

(In reply to Nils Ohlmeier [:drno] from comment #16)

So we are waiting for bug 1415755 which itself wait for Bug 1460346 in 63
get into Beta or Release.

(In reply to Alex Chronopoulos [:achronop] from comment #13)

A fix for this has been landed with Bug 1460346. Is there a way to check if
this issue has appeared again?

Bug 1460346 does not appear to have fixed this if we take bug 1460346 frequency as an indication, as bug 1460346 is still crashing in in 66 and 67.

This looks stalled to me. Karl what do you think?

Comment 18

[Karl Tomlinson (:karlt)]

Yes, these are stalled.

I don't know whether or not the bug 1415755 crashes still happening are the same as what was going wrong here.

We did have a flurry of reports around 2018-05, but none since, and it seems plausible that Alex's changes fixed this particular issue, and so I suggest closing this WFM.

Although the info here may still be useful for coming up with a theory for bug 1415755, it is referenced from bug 1415755 and so it doesn't matter whether this is open or not.