crash report on abort in AudioStreamAAudio::onErrorInThread

[jcusters]

I have noticed a crash report on our App from google play store, that reports an abort in
AudioStreamAAudio::onErrorInThread. ( Huawei HUAWEI Y9 2019 (HWJKM-H), Android 8.1)
due to the assert(stream == mAAudioStream.load());
I suppose this is due to some Thread timing or not locked issue ( stream already closed before..) ?
but isn't there a none crashing way to deal with this in the mean time ?

[dturner]

Yes, this can happen if the stream is already closed.

@philburk Could we do something better than use an assert here:

oboe/src/aaudio/AudioStreamAAudio.cpp

Line 270 in f4c4f4e

assert(stream == mAAudioStream.load());

[philburk]

If the stream was closed then it should not be calling back.
I don't generally like asserts. But this one indicates something truly wrong is happening.

@jcusters - What version of Oboe was that app running?

Were you using a callback or blocking read/write?

This may be related to:
Issue #359
PR #364

[jcusters]

Hi Phil,
It's the release 1.2 with using the callback method.

I realize that when the stream is closed due to an error like unplugging the device, that the app has to take action ( close the audio handling , give a message maybe even switch to another audio device ).
Although this is done through a Qt::QueuedConnection emitted signal, so in the main thread in the Qt Event handler, there is perhaps a small change that AudioStreamAAudio::close() is called in onErrorAfterClose() callback executed during AudioStreamAAudio::onErrorInThread.
Does AudioStreamAAudio::close() have a test inside if it's already closed ? or can the main thread test this ?
AudioStreamOpenSLES::close() has this test

[philburk]

Does AudioStreamAAudio::close() have a test inside if it's already closed ?

Yes, at:
https://github.com/google/oboe/blob/master/src/aaudio/AudioStreamAAudio.cpp#L234

there is perhaps a small change that AudioStreamAAudio::close() is called in onErrorAfterClose()

It should not call close because it has already been closed.
Where is close being called besides by Oboe in onErrorInThread()?

[milos-pesic-sc]

I was about to report the issue which I believe could be the same as this one.
We deployed our app with oboe audio engine to a testing group of couple of million users and this is the most frequent crash we have in the filed.
This is the part of the stack trace:

SIGABRT
Crashed: Thread
0  libc.so                         0xacbb13ce (Missing)
1  libc.so                         0xacbe6623 (Missing)
2  libc.so                         0xacbb15f3 (Missing)
3  libflipper_shared_android.so    0x82a273a8 (Missing)
4  libflipper_shared_android.so    0x8292e976 oboe::AudioStreamAAudio::onErrorInThread(AAudioStreamStruct*, oboe::Result) (AudioStreamAAudio.cpp:270)
5  libflipper_shared_android.so    0x8292eb1e _ZNSt6__ndk18__invokeIPFvPN4oboe17AudioStreamAAudioEP18AAudioStreamStructNS1_6ResultEEJS3_S5_S6_EEEDTclclsr3std6__ndk1E7forwardIT_Efp_Espclsr3std6__ndk1E7forwardIT0_Efp0_EEEOS9_DpOSA_ (type_traits:4323)
6  libc.so                         0xacbde5bf (Missing)
7  libc.so                         0xacbde5a7 (Missing)
8  libc.so                         0xacbb1f35 (Missing)
9  libc.so                         0xacbde5a7 (Missing)
10 libflipper_shared_android.so    0x8292eaea thread<void (&)(oboe::AudioStreamAAudio *, AAudioStreamStruct *, oboe::Result), oboe::AudioStreamAAudio *&, AAudioStreamStruct *&, oboe::Result, void> (memory)
11 libc.so                         0xacbafcc4 (Missing)

An example of last log lines we see in these reports:

399 | 1558682768340 | I/FlipperNative [2019-05-24 07:26:08.531617 (tid:3429284208)] - onErrorBeforeClose - Error on AudioStream : ErrorDisconnected
400 | 1558682768381 | I/FlipperNative [2019-05-24 07:26:08.531782 (tid:3429284208)] - onErrorBeforeClose - AudioStream device id: 688
401 | 1558682768384 | I/FlipperNative [2019-05-24 07:26:08.546191 (tid:3429284208)] - onErrorAfterClose - Error on AudioStream ErrorDisconnected
402 | 1558682768388 | I/FlipperNative [2019-05-24 07:26:08.546321 (tid:3429284208)] - restartStream - Restarting stream
403 | 1558682768395 | I/FlipperNative [2019-05-24 07:26:08.606789 (tid:3429284208)] - internalCreateStream - AudioStream opened. Device id: 688

These are messages we added in our error callbacks to be get some more info. We will have more crash reports soon and more logs - so hopefully that should provide better picture on what's happening.

I tried analysing the code and maybe - the use case when this crash may happen could be the one I described in the following comment: #524 (comment)
But according to the application logs we receive it doesn't seem to be the main cause.
Oboe version used: c278091
We are not closing the stream error callbacks.

[philburk]

Are you restarting the stream from the onErrorAfterClose call back? In that call back are you deleting the old stream? If so that could be a problem because you're being called from that stream.

[milos-pesic-sc]

We restart the stream in onErrorAfterClose in case of ErrorDisconnected and when doing so we reset a unique pointer holding the old stream object - which means we are deleting the old stream. While it requires a bit more caution (https://isocpp.org/wiki/faq/freestore-mgmt#delete-this) based on what I can see in oboe source code - none of the rules in the mentioned section are violated.
Nevertheless we can move that part out of the restart and delete the stream asynchronously. But I still think there is a possibility for hitting the mentioned assert if timing is right.
I will try to go through a scenario I saw could be problematic. The following steps are sequential ordered by time:

1. There is an error and oboe_aaudio_error_callback_proc gets called.
2. New thread is created and scheduled for execution:
   https://github.com/google/oboe/blob/master/src/aaudio/AudioStreamAAudio.cpp#L74
3. API consumer decides to close the stream and open a new one - not knowing that there is the error pending - so AudioStreamAAudio::close gets called reseting mAAudioStream to nullptr.
4. Thread created in step 2 for handling error on now closed stream gets the context and the first thing it does in AudioStreamAAudio::onErrorInThread is asserting on AAudioStream* equality. This assertion fails now because mAAudioStream is reset to nullptr in a meanwhile.

Maybe I am missing something - apologies if that's the case.

Also having in mind async nature of error handling - when is a good time to delete oboe stream if needed after step 2 mentioned above - and how we could be sure that stream we are deleting isn't used by oboe error handling logic i.e in step 4?

[milos-pesic-sc]

Could successive "stream disconnected" events as mentioned here: https://github.com/google/oboe/blob/master/samples/hello-oboe/src/main/cpp/PlayAudioEngine.cpp#L287
lead to the same crash without the API consumer closing the stream explicitly when the error is about to happen?
If by any chance we have two successive callbacks, creating two threads - the same scenario as described above may happen.
Not sure what's the status of the internal issue mentioned there..

[philburk]

The issue b/63087953 involving two onError callbacks occurring was supposedly fixed in 8.1. But it still may be happening. That could account for this error:

A - AAudio calls error callback launches handling thread "C"
B - AAudio calls error callback launches second handling thread "D"
C - runs and closes aaudio stream
D - runs and asserts because aaudio stream pointer now null

I will prevent that race by blocking the handling of the second callback B.