AudioStreamAAudio::write crashes if callback is not set #359

loongee · 2019-01-21T12:41:41Z

In my own project, the oboe library is used as follows:

// create builder_ but leave callback to nullptr
// ...
oboe::Result result = builder_.openStream(&stream);
if (result == oboe::Result::OK) {
    // start new thread(writting_data)
}

// create a new thread running
void writting_data() {
    while (true) {
        // read some data from pool into buffer
        // ...
        if (!stream->write(buffer, size, 100ms)) {
            break;
        }
    }
}

Many crashes reported from different devices with Android 8.1 and Android 9 as follows:

SIGSEGV(SEGV_MAPERR):
#00 pc 00009878 /system/lib/libutils.so (_ZNK7android7RefBase9decStrongEPKv+11) [armeabi-v7a::272d48b5b3797e25b22d892c522d65f3]
#1 pc 0003568d /system/lib/libaudioclient.so (_ZN7android10AudioTrack12obtainBufferEPNS0_6BufferEPK8timespecPS3_Pj+340) [armeabi-v7a::9288d003accbbf5c81e4a1c1b845b0c1]
#2 pc 00035a1d /system/lib/libaudioclient.so (_ZN7android10AudioTrack5writeEPKvjb+492) [armeabi-v7a::9288d003accbbf5c81e4a1c1b845b0c1]
#3 pc 0001510b /system/lib/libaaudio.so (_ZN6aaudio16AudioStreamTrack5writeEPKvix+74) [armeabi-v7a::0228245fd2eaf0ea6afd7b3194382e9d]
#4 pc 003a98a7 /data/app/com.xxx.xxx-7auN8JsRoRbrjFft8dP01Q==/lib/arm/player-lib.so (_ZN4oboe17AudioStreamAAudio5writeEPKvix+50) [armeabi-v7a::de1dfbeb99205ca392b18fc844c4926b]

and logcat:

01-21 12:26:54.960 12208 14284 I AAudioStream: open() rate = 48000, channels = 2, format = 1, sharing = SH, dir = OUTPUT
01-21 12:26:54.960 12208 14284 I AAudioStream: open() device = 0, sessionId = 0, perfMode = 12, callback: OFF with frames = 0
01-21 12:26:54.960 12208 14284 I AAudioStream: open() usage = 1, contentType = 3, inputPreset = 6
01-21 12:26:54.960 12208 14284 D AudioStreamTrack: open(), request notificationFrames = 0, frameCount = 0
01-21 12:26:54.961 12208 14284 W AudioTrack: AUDIO_OUTPUT_FLAG_FAST denied by client, not shared buffer and transfer = TRANSFER_SYNC
01-21 12:26:54.961 12208 14297 W MapperHal: buffer descriptor with invalid usage bits 0x2000
01-21 12:26:54.966 12208 14284 W AudioStreamTrack: open() flags changed from 0x00000104 to 0x00000000
01-21 12:26:54.967 12208 14284 W AudioStreamTrack: open() perfMode changed from 12 to 10
01-21 12:26:54.967 12208 14284 D AAudio : AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for (0xbef21d40) ----------------
01-21 12:26:54.971 12208 14284 D AAudio : AAudioStream_requestStart(0xbef21d40) called --------------
01-21 12:26:54.971 12208 14284 D : PlayerBase::start() from IPlayer
01-21 12:26:54.980 12208 12208 W weex : Warning :Component tree has not build completely,onActivityStart can not be call!
01-21 12:26:54.980 12208 12208 W weex : Warning :Component tree has not build completely, onActivityResume can not be call!
01-21 12:26:54.985 12208 14284 D AAudio : AAudioStream_requestStart(0xbef21d40) returned 0 ---------
01-21 12:26:54.985 12208 12227 D AudioStreamLegacy: onAudioDeviceUpdate() deviceId 2
01-21 12:26:54.985 12208 12227 D AudioStreamLegacy: onAudioDeviceUpdate() DISCONNECT the stream now
01-21 12:26:54.988 12208 14304 D AAudio : AAudioStream_requestStop(0xbef21d40)
01-21 12:26:54.988 12208 14304 D : PlayerBase::stop() from IPlayer
01-21 12:26:54.988 12208 14304 E AAudioStream: setState(0xbef21d40) tried to set to 9 but already DISCONNECTED
01-21 12:26:54.988 12208 14304 D AudioTrack: stop() called with 0 frames delivered
01-21 12:26:54.989 12208 14297 I ACodec : [OMX.hisi.video.decoder.hevc] got color aspects (R:2(Limited), P:1(BT709_5), M:3(BT601_6), T:3(SMPTE170M)) err=0(NO_ERROR)
01-21 12:26:54.989 12208 14297 I ACodec : [OMX.hisi.video.decoder.hevc] got color aspects (R:2(Limited), P:1(BT709_5), M:3(BT601_6), T:3(SMPTE170M)) err=0(NO_ERROR)
01-21 12:26:54.989 12208 14297 I ACodec : [OMX.hisi.video.decoder.hevc] using color aspects (R:2(Limited), P:3(BT601_6_625), M:3(BT601_6), T:3(SMPTE170M)) and dataspace 0x102
01-21 12:26:54.989 12208 14297 I ACodec : [OMX.hisi.video.decoder.hevc] got color aspects (R:2(Limited), P:1(BT709_5), M:3(BT601_6), T:3(SMPTE170M)) err=0(NO_ERROR)
01-21 12:26:54.989 12208 14297 I ACodec : [OMX.hisi.video.decoder.hevc] got color aspects (R:2(Limited), P:1(BT709_5), M:3(BT601_6), T:3(SMPTE170M)) err=0(NO_ERROR)
01-21 12:26:54.989 12208 14297 I ACodec : [OMX.hisi.video.decoder.hevc] using color aspects (R:2(Limited), P:3(BT601_6_625), M:3(BT601_6), T:3(SMPTE170M)) and dataspace 0x102
01-21 12:26:54.989 12208 14304 D AAudio : AAudioStream_close(0xbef21d40) called ---------------
01-21 12:26:54.991 12208 14304 D AAudioStream: destroying 0xbef21d40, state = AAUDIO_STREAM_STATE_CLOSED
01-21 12:26:54.991 12208 14304 D AAudio : AAudioStream_close(0xbef21d40) returned 0 ---------
01-21 12:26:55.024 12208 14297 D SurfaceUtils: disconnecting from surface 0xa9f9a808, reason setNativeWindowSizeFormatAndUsage
01-21 12:26:55.027 12208 14297 D SurfaceUtils: connecting to surface 0xa9f9a808, reason setNativeWindowSizeFormatAndUsage
01-21 12:26:55.028 12208 14297 D SurfaceUtils: set up nativeWindow 0xa9f9a808 for 1920x1088, color 0x30d, rotation 0, usage 0x20002900
01-21 12:26:55.028 12208 14297 W ACodec : [OMX.hisi.video.decoder.hevc] setting nBufferCountActual to 16 failed: -2147483648
01-21 12:26:55.028 12208 14297 W MapperHal: buffer descriptor with invalid usage bits 0x2000
01-21 12:26:55.033 12208 14297 W MapperHal: buffer descriptor with invalid usage bits 0x2000
01-21 12:26:55.034 12208 12208 D GuardianMedalDraweeSpan: onAttach
01-21 12:26:55.034 12208 12208 D GuardianMedalDraweeSpan: submitRequest urls is [http://shp.qpic.cn/pggamehead/0/1542087758_941_96x36/0?new=1.0&w=96&h=36]
01-21 12:26:55.040 12208 14297 W MapperHal: buffer descriptor with invalid usage bits 0x2000
01-21 12:26:55.042 12208 14297 W MapperHal: buffer descriptor with invalid usage bits 0x2000
01-21 12:26:55.045 12208 14297 W MapperHal: buffer descriptor with invalid usage bits 0x2000
01-21 12:26:55.047 12208 14297 W MapperHal: buffer descriptor with invalid usage bits 0x2000
01-21 12:26:55.053 12208 14297 W MapperHal: buffer descriptor with invalid usage bits 0x2000
01-21 12:26:55.055 12208 14297 W MapperHal: buffer descriptor with invalid usage bits 0x2000
01-21 12:26:55.059 12208 14297 W MapperHal: buffer descriptor with invalid usage bits 0x2000
01-21 12:26:55.062 12208 14297 W MapperHal: buffer descriptor with invalid usage bits 0x2000
01-21 12:26:55.064 12208 14297 W MapperHal: buffer descriptor with invalid usage bits 0x2000
01-21 12:26:55.067 12208 14297 W MapperHal: buffer descriptor with invalid usage bits 0x2000
--------- beginning of crash

The reason (not 100% sure):
In AudioStreamAAudio's error handler, it calls close()

void AudioStreamAAudio::onErrorInThread(AAudioStream *stream, Result error) {
    LOGD("onErrorInThread() - entering ===================================");
    assert(stream == mAAudioStream.load());
    requestStop();
    if (mStreamCallback != nullptr) {
        mStreamCallback->onErrorBeforeClose(this, error);
    }
    close();
    if (mStreamCallback != nullptr) {
        mStreamCallback->onErrorAfterClose(this, error);
    }
    LOGD("onErrorInThread() - exiting ===================================");
}

Result AudioStreamAAudio::close() {
    // The main reason we have this mutex if to prevent a collision between a call
    // by the application to stop a stream at the same time that an onError callback
    // is being executed because of a disconnect. The close will delete the stream,
    // which could otherwise cause the requestStop() to crash.
    std::lock_guard<std::mutex> lock(mLock);

    AudioStream::close();

    // This will delete the AAudio stream object so we need to null out the pointer.
    AAudioStream *stream = mAAudioStream.exchange(nullptr);
    if (stream != nullptr) {
        return static_cast<Result>(mLibLoader->stream_close(stream));
    } else {
        return Result::ErrorClosed;
    }
}

but in write function:

ResultWithValue<int32_t>   AudioStreamAAudio::write(const void *buffer,
                                     int32_t numFrames,
                                     int64_t timeoutNanoseconds) {
    AAudioStream *stream = mAAudioStream.load();
    if (stream != nullptr) {
        // !!! the pointer stored in mAAudioStream could be closed and freed at this time !!!
        int32_t result = mLibLoader->stream_write(mAAudioStream, buffer,
                                                  numFrames, timeoutNanoseconds);
        return ResultWithValue<int32_t>::createBasedOnSign(result);
    } else {
        return ResultWithValue<int32_t>(Result::ErrorClosed);
    }
}

The problem is:
If I use error callbacks to prevent freeing resource when writing, then write function is useless (onDataReady callback is set at the same time);
if not using callbacks, write is not safe.

Solution:
Maybe a lock guard is needed in write function,
or error callback and dataReady callback can be split into different callback.

The text was updated successfully, but these errors were encountered:

philburk · 2019-01-21T21:38:08Z

It looks like the DISCONNECT is happening immediately. Why? Please provide more information about the devices, OS and Oboe versions, and the app.

01-21 12:26:54.985 12208 14284 D AAudio : AAudioStream_requestStart(0xbef21d40) returned 0
01-21 12:26:54.985 12208 12227 D AudioStreamLegacy: onAudioDeviceUpdate() DISCONNECT the stream now

In Oboe, the errorCallback is enabled even is the data callback is not enabled.
https://github.com/google/oboe/blob/master/src/aaudio/AudioStreamAAudio.cpp#L162

If the error callback is called while the apps writing thread is running then it will crash. That is a problem. It will result in a call to onErrorInThread(), which closes the stream.

oboe/src/aaudio/AudioStreamAAudio.cpp

Line 259 in 6fa2a1a

void AudioStreamAAudio::onErrorInThread(AAudioStream *stream, Result error) {

We will fix this. The easiest fix may be to not set the error callback if there is no data callback.
The close should only happen if the write() returns a DISCONNECT error message.

Thanks for reporting this.

loongee · 2019-01-22T03:10:40Z

This log is extracted from the following device:

Model: HUAWEI P20 Pro
ROM：HuaWei/EMOTION/EmotionUI_9.0.0
OS: Android 9, level 28
oboe version: 1.1.1 reversion: 8cc0148

Our app can be obtained via: http://dldir1.qq.com//egame/qgame/4.3.0/408/qgame_4.3.0.370.755_r836e9a_firstgray_release.apk
(Chinese version only, but because of the crash, we have forced all users to use oboe_openSLES for now, aaudio is disabled, so the app can not reproduce the crash)

After analyzing several users' log who have the same crash, DISCONNECT happening immediately after open() is not the common situation, it's much more like a coincidence.

Disable error callback when data callback is absent is a good idea, because the close() will set stream pointer to null, that will cause write() returning ErrorClosed, ErrorDisconnected is missed.

philburk · 2019-01-23T01:35:13Z

Thanks for the info.

Is the crash associated with a DISCONNECT event? Like unplugging headphones?

Can you consistently reproduce the crash in your office? Or do you only get reports from users?

If you can reproduce it, please try moving the setting of the error callback into the conditional, like this:

if (mStreamCallback != nullptr) {
    mLibLoader->builder_setDataCallback(aaudioBuilder, oboe_aaudio_data_callback_proc, this);
    mLibLoader->builder_setFramesPerDataCallback(aaudioBuilder, getFramesPerCallback());

    mLibLoader->builder_setErrorCallback(aaudioBuilder, oboe_aaudio_error_callback_proc, this); // !!
}

We are considering this fix. But we also need to look more carefully at protecting the stream pointer from close().

loongee · 2019-01-23T03:17:32Z

Yes, almost every crash is related with DISCONNECT event.
This crash is not easy to reproduce, about (10 times / 10000 users) per day, they're all reported from users. We tried to reproduce the crash by plugging or unplugging the headphone(plugging or unplugging the headphones can both produce DISCONNECT event):

2019-01-23 10:47:58.291 23556-1578/com.xxx.xxx D/AudioStreamLegacy: onAudioDeviceUpdate() deviceId 2
2019-01-23 10:47:58.291 23556-1578/com.xxx.xxx D/AudioStreamLegacy: onAudioDeviceUpdate() DISCONNECT the stream now

but no crash happened.
so the change can only be verified until we release a new version for users.

dturner · 2019-01-29T17:56:59Z

@philburk to implement workaround for this bug.

This bug points out a larger problem which is the "use after close" issue. We should consider separating the data callback from the error callback interface.

That can close a stream that is in use by the app thread that is writing the stream. See issue #359

philburk · 2019-01-30T00:33:24Z

There is a pending fix at #364

philburk · 2019-02-04T23:15:27Z

loongee wrote:

Maybe a lock guard is needed in write function,

Yes, or something to prevent write() and close() from colliding,

philburk · 2019-02-16T23:13:53Z

I believe that #364 solves this particular problem.

There is also a problem if an app closes a stream from one thread while writing from another thread. That is a different problem that can and should be prevented by the app. So I will close this.

philburk · 2019-06-12T22:49:28Z

See also related bug #519

darshanbr · 2021-05-23T07:36:30Z

Hi @philburk @dturner

It would be more helpful to debug if you explain why and when onAudioDeviceUpdate() method will be triggered ?

2019-01-23 10:47:58.291 23556-1578/com.xxx.xxx D/AudioStreamLegacy: onAudioDeviceUpdate() deviceId 2
2019-01-23 10:47:58.291 23556-1578/com.xxx.xxx D/AudioStreamLegacy: onAudioDeviceUpdate() DISCONNECT the stream

Thanks

philburk · 2021-05-23T14:41:40Z

onAudioDeviceUpdate() is an internal method inside AAudio. It is called when there is a routing change, for example when a headset is plugged in or unplugged. It can also happen if "playback capture" is initiated. onAudioDeviceUpdate() is part of the Legacy data path.

For MMAP, it can also happen if an EXCLUSIVE stream is converted to a SHARED stream because another app needs low latency. That can happen on R and later.

darshanbr · 2021-05-23T16:38:51Z

@philburk @dturner

On Android R we are facing AAudio stream disconnection issue. Bluetooth will be playing initially(which uses AAudio). AAudio stream is being disconnected as soon as we switched from Bluetooth to radio. Therefore there is no audio available once after we switched back from radio to Bluetooth.

03-29 13:31:21.374 3555 6534 W APM_AudioPolicyManager: disconnectAudioSource source has neither SW nor HW output
03-29 13:31:21.374 3555 6534 E APM_AudioPolicyManager: releaseAudioPatchInternal: no patch found with handle=0
03-29 13:31:21.391 4651 8205 D AudioStreamLegacy: onAudioDeviceUpdate() devId 3 => 2
03-29 13:31:21.391 4651 8205 D AudioStreamLegacy: onAudioDeviceUpdate() DISCONNECT the stream now
03-29 13:31:21.391 4651 8205 D AAudioStream: setState(s#2) from 4 to 13
03-29 13:31:21.392 3555 3592 D AF::TrackHandle: OpPlayAudio: not muting track:68 usage:0 for service UID 1041
03-29 13:31:21.392 3555 3567 E AudioFlinger::PatchPanel: Software patch connections leaked 268 276
03-29 13:31:21.392 3555 3567 E AudioFlinger::PatchPanel: A non empty Patch Endpoint leaked, handle 268
03-29 13:31:21.392 3555 3567 E AudioFlinger::PatchPanel: A non empty Patch Endpoint leaked, handle 276
03-29 13:31:21.393 4651 4651 I bt_btif_a2dp_sink: btif_a2dp_sink_set_focus_state_req
03-29 13:31:21.393 4651 5580 I bt_btif_a2dp_sink: btif_a2dp_sink_set_focus_state_event: state=0

our system property configurations are as below
PRODUCT_PROPERTY_OVERRIDES += aaudio.mmap_policy=1
PRODUCT_PROPERTY_OVERRIDES += aaudio.mmap_exclusive_policy=1

it's an always issue and we can reproduce it anytime. could you please explain what's going wrong here ?

philburk · 2021-05-24T01:06:31Z

@darshanbr - You are adding a new bug to an issue that is already closed. For new bugs please start a new Issue at: https://github.com/google/oboe/issues/new/choose

dturner assigned philburk Jan 21, 2019

philburk added bug P1 high priority labels Jan 21, 2019

This was referenced Jan 23, 2019

AAudioStream_close crashes on Android 8.1 #361

Closed

OpenSLES GetPosition crashes on Android 8.0 to Android 9 #362

Closed

dturner added this to the future milestone Jan 29, 2019

philburk pushed a commit that referenced this issue Jan 30, 2019

oboe: do not use error callback when no data callback

c35ea6f

That can close a stream that is in use by the app thread that is writing the stream. See issue #359

philburk mentioned this issue Jan 30, 2019

oboe: do not use error callback when no data callback #364

Merged

philburk closed this as completed Feb 16, 2019

philburk mentioned this issue May 23, 2019

crash report on abort in AudioStreamAAudio::onErrorInThread #519

Closed

philburk mentioned this issue Jun 10, 2019

aaudio crash, assert in releaseBuffer #535

Closed

iNeverSleeeeep mentioned this issue May 9, 2020

crash on Android 10,level 29 when stream disconnected #849

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

AudioStreamAAudio::write crashes if callback is not set #359

AudioStreamAAudio::write crashes if callback is not set #359

loongee commented Jan 21, 2019

philburk commented Jan 21, 2019

loongee commented Jan 22, 2019 •

edited

Loading

philburk commented Jan 23, 2019

loongee commented Jan 23, 2019

dturner commented Jan 29, 2019

philburk commented Jan 30, 2019

philburk commented Feb 4, 2019

philburk commented Feb 16, 2019

philburk commented Jun 12, 2019

darshanbr commented May 23, 2021 •

edited

Loading

philburk commented May 23, 2021

darshanbr commented May 23, 2021 •

edited

Loading

philburk commented May 24, 2021

AudioStreamAAudio::write crashes if callback is not set #359

AudioStreamAAudio::write crashes if callback is not set #359

Comments

loongee commented Jan 21, 2019

philburk commented Jan 21, 2019

loongee commented Jan 22, 2019 • edited Loading

philburk commented Jan 23, 2019

loongee commented Jan 23, 2019

dturner commented Jan 29, 2019

philburk commented Jan 30, 2019

philburk commented Feb 4, 2019

philburk commented Feb 16, 2019

philburk commented Jun 12, 2019

darshanbr commented May 23, 2021 • edited Loading

philburk commented May 23, 2021

darshanbr commented May 23, 2021 • edited Loading

philburk commented May 24, 2021

loongee commented Jan 22, 2019 •

edited

Loading

darshanbr commented May 23, 2021 •

edited

Loading

darshanbr commented May 23, 2021 •

edited

Loading