Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Crash when headset plugs in/out #406

Closed
pokey909 opened this issue Mar 15, 2019 · 14 comments
Closed

Crash when headset plugs in/out #406

pokey909 opened this issue Mar 15, 2019 · 14 comments
Assignees
Labels
bug P1 high priority
Milestone

Comments

@pokey909
Copy link

The crash happens when the stream is in Paused state and a headset gets connected or disconnected.

Next time you call play() (the synchronous API) we get the crash.
And the reason seems to be that as soon as the stream starts again, it will call onErrorInThread on the stream since it is now in DISCONNECTED state and delegate to onErrorAfterClose functions which run in their own detached thread.
We restart the stream in the callbacks but the stream will be closed. Concurrently, the start() function will run waitForStateChange which is not supposed to be called during or after close(). And here the crash happens since the underlying stream got deleted.

I can work around that problem by only using the requestStart() function since it doesn't call waitForStateTransition .

Are we not supposed to use the synchronous methods at all? I don't see a way to make that threadsafe unless we use locks to synchronize the detached thread from oboe_aaudio_error_callback_proc with the waitForStateTransition method.

Stacktrace below:

2019-03-15 14:17:28.570 3794-3823/com.soundcloud.flipper I/FlipperNative: 2019-03-15 13:17:28.570181 (tid:4152329364) play - play() API invoked.
2019-03-15 14:17:28.570 3794-3823/com.soundcloud.flipper I/FlipperNative: 2019-03-15 13:17:28.570310 (tid:4152329364) post - Posting Play ...
2019-03-15 14:17:28.570 3794-3823/com.soundcloud.flipper D/FlipperNative: 2019-03-15 13:17:28.570533 (tid:3598301552) operator() - Processing Play event.
2019-03-15 14:17:28.570 3794-3823/com.soundcloud.flipper W/FlipperNative: 2019-03-15 13:17:28.570649 (tid:3598301552) playing_action - PLAY ACTION
2019-03-15 14:17:28.571 3794-3823/com.soundcloud.flipper I/FlipperNative: 2019-03-15 13:17:28.570739 (tid:3598301552) on_entry - Entering state: Playing
2019-03-15 14:17:28.571 3794-3823/com.soundcloud.flipper D/FlipperNative: 2019-03-15 13:17:28.571215 (tid:3598301552) start - OBOE START
2019-03-15 14:17:28.571 3794-3827/com.soundcloud.flipper D/AAudio: AAudioStream_requestStart(0xece7fd00) called --------------
2019-03-15 14:17:28.571 3794-3823/com.soundcloud.flipper D/FlipperNative: 2019-03-15 13:17:28.571518 (tid:3598301552) start - Oboe start!
2019-03-15 14:17:28.576 3794-3827/com.soundcloud.flipper D/AAudio: AAudioStream_requestStart(0xece7fd00) returned 0 ---------
2019-03-15 14:17:28.576 3794-3812/com.soundcloud.flipper D/AudioStreamLegacy: onAudioDeviceUpdate() deviceId 498
2019-03-15 14:17:28.576 3794-3812/com.soundcloud.flipper D/AudioStreamLegacy: onAudioDeviceUpdate() request DISCONNECT in data callback due to device change
2019-03-15 14:17:28.576 3794-3847/com.soundcloud.flipper D/AudioStreamLegacy: checkForDisconnectRequest() mRequestDisconnect acknowledged
2019-03-15 14:17:28.576 3794-3847/com.soundcloud.flipper W/AudioStreamLegacy: processCallbackCommon() data, stream disconnected
2019-03-15 14:17:28.576 3794-3847/com.soundcloud.flipper E/AudioTrack: EVENT_MORE_DATA requested 3072 bytes but callback returned -1 bytes
2019-03-15 14:17:28.577 3794-3855/com.soundcloud.flipper D/OboeAudio: onErrorInThread() - entering ===================================
2019-03-15 14:17:28.577 3794-3855/com.soundcloud.flipper D/AAudio: AAudioStream_requestStop(0xece7fd00)
2019-03-15 14:17:28.577 3794-3855/com.soundcloud.flipper E/AAudioStream: setState(0xece7fd00) tried to set to 9 but already DISCONNECTED
2019-03-15 14:17:28.577 3794-3855/com.soundcloud.flipper D/AudioTrack: stop() called with 167232 frames delivered
2019-03-15 14:17:28.577 3794-3855/com.soundcloud.flipper D/AAudio: AAudioStream_close(0xece7fd00) called ---------------
2019-03-15 14:17:28.594 3794-3855/com.soundcloud.flipper D/AAudioStream: destroying 0xece7fd00, state = AAUDIO_STREAM_STATE_CLOSED
2019-03-15 14:17:28.594 3794-3855/com.soundcloud.flipper D/AAudio: AAudioStream_close(0xece7fd00) returned 0 ---------
2019-03-15 14:17:28.595 3794-3855/com.soundcloud.flipper D/OboeAudio: onErrorInThread() - exiting ===================================
2019-03-15 14:17:28.595 3794-3823/com.soundcloud.flipper D/FlipperNative: 2019-03-15 13:17:28.594950 (tid:3542088048) onErrorAfterClose - Restart stream operation already in progress - ignoring this request
2019-03-15 14:17:28.596 3794-3827/com.soundcloud.flipper E/libc++abi: Pure virtual function called!
2019-03-15 14:17:28.596 3794-3827/com.soundcloud.flipper A/libc: Fatal signal 6 (SIGABRT), code -6 (SI_TKILL) in tid 3827 (Thread-23), pid 3794 (ndcloud.flipper)
2019-03-15 14:17:28.623 3858-3858/? I/crash_dump32: obtaining output fd from tombstoned, type: kDebuggerdTombstone
2019-03-15 14:17:28.623 1743-1743/? I//system/bin/tombstoned: received crash request for pid 3827
2019-03-15 14:17:28.624 3858-3858/? I/crash_dump32: performing dump of process 3794 (target tid = 3827)
2019-03-15 14:17:28.628 3858-3858/? A/DEBUG: *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
2019-03-15 14:17:28.628 3858-3858/? A/DEBUG: Build fingerprint: 'google/sdk_gphone_x86/generic_x86:9/PSR1.180720.075/5124027:user/release-keys'
2019-03-15 14:17:28.628 3858-3858/? A/DEBUG: Revision: '0'
2019-03-15 14:17:28.628 3858-3858/? A/DEBUG: ABI: 'x86'
2019-03-15 14:17:28.628 3858-3858/? A/DEBUG: pid: 3794, tid: 3827, name: Thread-23  >>> com.soundcloud.flipper <<<
2019-03-15 14:17:28.628 3858-3858/? A/DEBUG: signal 6 (SIGABRT), code -6 (SI_TKILL), fault addr --------
2019-03-15 14:17:28.628 3858-3858/? A/DEBUG: Abort message: 'Pure virtual function called!'
2019-03-15 14:17:28.628 3858-3858/? A/DEBUG:     eax 00000000  ebx 00000ed2  ecx 00000ef3  edx 00000006
2019-03-15 14:17:28.628 3858-3858/? A/DEBUG:     edi 00000ed2  esi d679a964
2019-03-15 14:17:28.628 3858-3858/? A/DEBUG:     ebp d679a918  esp d679a8a8  eip f76aeb39
2019-03-15 14:17:28.636 3858-3858/? A/DEBUG: backtrace:
2019-03-15 14:17:28.636 3858-3858/? A/DEBUG:     #00 pc 00000b39  [vdso:f76ae000] (__kernel_vsyscall+9)
2019-03-15 14:17:28.636 3858-3858/? A/DEBUG:     #01 pc 0001fdf8  /system/lib/libc.so (syscall+40)
2019-03-15 14:17:28.636 3858-3858/? A/DEBUG:     #02 pc 00022ed3  /system/lib/libc.so (abort+115)
2019-03-15 14:17:28.636 3858-3858/? A/DEBUG:     #03 pc 00033e07  /system/lib/libc++.so (abort_message+151)
2019-03-15 14:17:28.636 3858-3858/? A/DEBUG:     #04 pc 0004b643  /system/lib/libc++.so (__cxa_pure_virtual+35)
2019-03-15 14:17:28.636 3858-3858/? A/DEBUG:     #05 pc 00012a3f  /system/lib/libaaudio.so (aaudio::AudioStream::waitForStateChange(int, int*, long long)+239)
2019-03-15 14:17:28.636 3858-3858/? A/DEBUG:     #06 pc 0001455d  /system/lib/libaaudio.so (AAudioStream_waitForStateChange+45)
2019-03-15 14:17:28.636 3858-3858/? A/DEBUG:     #07 pc 00c9a4a6  /data/app/com.soundcloud.flipper-q6lKnSNaQwXGoyG2jis7Bw==/lib/x86/libflipper_shared_androidd.so (oboe::AudioStreamAAudio::waitForStateChange(oboe::StreamState, oboe::StreamState*, long long)+70)
2019-03-15 14:17:28.637 3858-3858/? A/DEBUG:     #08 pc 00c9aea6  /data/app/com.soundcloud.flipper-q6lKnSNaQwXGoyG2jis7Bw==/lib/x86/libflipper_shared_androidd.so (oboe::AudioStream::waitForStateTransition(oboe::StreamState, oboe::StreamState, long long)+86)
2019-03-15 14:17:28.637 3858-3858/? A/DEBUG:     #09 pc 00c9af0d  /data/app/com.soundcloud.flipper-q6lKnSNaQwXGoyG2jis7Bw==/lib/x86/libflipper_shared_androidd.so (oboe::AudioStream::start(long long)+61)
2019-03-15 14:17:28.637 3858-3858/? A/DEBUG:     #10 pc 00ae6d52  /data/app/com.soundcloud.flipper-q6lKnSNaQwXGoyG2jis7Bw==/lib/x86/libflipper_shared_androidd.so (sinks::android::details::OboeEngine::Private::start()+226)
2019-03-15 14:17:28.637 3858-3858/? A/DEBUG:     #11 pc 00ae4e8e  /data/app/com.soundcloud.flipper-q6lKnSNaQwXGoyG2jis7Bw==/lib/x86/libflipper_shared_androidd.so (sinks::android::details::OboeEngine::start()+126)
2019-03-15 14:17:28.637 3858-3858/? A/DEBUG:     #12 pc 00883bcd  /data/app/com.soundcloud.flipper-q6lKnSNaQwXGoyG2jis7Bw==/lib/x86/libflipper_shared_androidd.so (sinks::android::Oboe::OboeSink::onStart()+269)
@philburk
Copy link
Collaborator

What version of Oboe are you using?

I think that may have been fixed in this Pull Request:
#364

Please let me know if that fixes the problem.

It is probably worth releasing a new stable version with that fix.

@pokey909
Copy link
Author

pokey909 commented Mar 16, 2019

Hi Phil, thanks for the quick reply. I just tested with master and it still crashes.
From what I can see the problem is not that the callback is running, but that the the start() function does 2 things:

  1. async start the stream, which also has to trigger the disconnected notification via error callback to restart the stream. But this runs in its own detached thread which leads to problems with 2.
  2. wait for a state change. It is not allowed to call this during or after a close(). The close will happen however as a result from 1. If the timing is right, either close was already called or is concurrently executing with waitForStateTransition.

To me it sounds like start() should be avoided in its current form unless close() and waitForStateTransition are synchronized.

Please correct me if that doesn't sound right.

@pokey909
Copy link
Author

pokey909 commented Mar 16, 2019

I just realized that close already locks a mutex.
If I synchronize close with waitForStateTransition, the crash is fixed. But its more like a workaround than a real fix since this function is not supposed to be locked i believe. Also the atomic load doesn't make sense then anymore.

Result AudioStreamAAudio::waitForStateChange(StreamState currentState,
                                        StreamState *nextState,
                                        int64_t timeoutNanoseconds) {
    std::lock_guard<std::mutex> lock(mLock); // <- but now it shouldn't be used in time critical code anymore
    AAudioStream *stream = mAAudioStream.load();
    if (stream != nullptr) {
...

@philburk
Copy link
Collaborator

@pokey909 - I appreciate your help with this Issue. We want to get it right.

You wrote:

the start() function does 2 things:
async start the stream, which also has to trigger the disconnected notification via error
callback to restart the stream. But this runs in its own detached thread which leads to
problems with 2.

Oh! Are you using a data callback? I was thinking you were using read/write. Then yes, the synchronous start() method does have a problem. The wait method starts running while the stream still exists. Then the stream gets deleted while it is still waiting. Not good.

To me it sounds like start() should be avoided in its current form

I agree. We will probably deprecate it. Calling requestStart() is better. The waitForStateChange() method is dangerous when combined with the asynchronous close in the error callback. I wish we could use recursive locks.

Thanks for reporting this.

@philburk philburk self-assigned this Mar 18, 2019
@philburk philburk added bug P1 high priority labels Mar 18, 2019
@pokey909
Copy link
Author

I don't think recursive mutexes are needed.
Unless waitForStateTransition has to remain lock-free, we can simply lock mLock as I did in #409 since that serializes waitForStateTransition and close().
Does that make sense?

@dturner
Copy link
Collaborator

dturner commented Mar 19, 2019

Actions:

  • Remove waitForStateChange from start
  • Deprecate synchronous start pause and stop methods
  • Internal proposal: Modify the AAudio API to split close and destroy. Add a release resources method.

@pokey909
Copy link
Author

So what is the suggested way to wait for a state change then?
A user is still able to call waitForStateChange right after calling requestStart.

@philburk
Copy link
Collaborator

So what is the suggested way to wait for a state change then?

Generally, one does not need to call waitForStateChange(). When starting you can just call requestStart(). You don't really need to wait for the internal state change.
And it is not really safe to call waitForStateChange() when the stream is running.
So I think we should remove it from the start() method.

One time you might want to waitForStateChange() is when doing a flush and you want to make sure the stream is PAUSED. But the stream and callbacks are not running when paused so it is safe to call waitForStateChange(). Maybe the wait should be moved to the beginning of the flush() method.

@philburk
Copy link
Collaborator

There may be a way to make waitForStateChange() safer. The problem is that we call into AAudioStream_waitForStateChange() and sleep in that routine. We don't want to sleep with the lock.

So we could instead just sleep in our Oboe method and call AAudioStream_waitForStateChange() with a timeout=0. That way the AAudio function will not block. So we could safely surround that with a lock. Then unlock around the sleep in Oboe. Then the Oboe waitForStateChange() would be synchronized with the close and would be safe.

@philburk philburk added this to the v1.2 milestone Mar 27, 2019
@pokey909
Copy link
Author

Thanks for clarifying Phil.
That sounds pretty good. Especially since that doesn't require an AAudio update. this would allow us to continue rolling out Oboe in our A/B test.

philburk pushed a commit that referenced this issue Mar 28, 2019
Call AAudio with timeout zero to avoid blocking.
Prevent crashes if close() called from another thread.

Possible fix for #406
philburk pushed a commit that referenced this issue Mar 28, 2019
Do not return ErrorTimeout is user passed timeout==0.

Related to #406
philburk pushed a commit that referenced this issue Mar 28, 2019
@philburk
Copy link
Collaborator

philburk commented Apr 5, 2019

@pokey909 The current master might fix this. It now uses locks in waitForStateChange() in a way that will not block other threads.
Can you please retest your app?

@milos-pesic-sc
Copy link

@philburk Alex is on vacation - so I will retest the app with the latest changes and report back.

@milos-pesic-sc
Copy link

@philburk We are not able to reproduce the issue anymore with the current master.

@philburk
Copy link
Collaborator

Thanks. That is great news. I will close this Issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug P1 high priority
Projects
None yet
Development

No branches or pull requests

4 participants