Android Crash 2 - Githubissues

kiranb47 commented 1 year ago

axmol version:
devices test on:
developing environments
- NDK version: r19c
- Xcode version: 12.4
- Visual Studio:
  - VS version: 2019 (16.11), 2022 (17.4)
  - MSVC version: 1929, 1934
  - Windows SDK version: 10.0.22621.0
- cmake version: Steps to Reproduce:

We have migrated our Match Animal game to Axmol from Cocos2dx V3 latest yesterday. Getting this crash now. How to fix this issue?

terminating with uncaught exception of type al::backend_exception: Failed to stop stream: ErrorClosed

  #00  pc 0x00000000000534d4  /apex/com.android.runtime/lib64/bionic/libc.so (abort+164)
  #01  pc 0x00000000000d1fcc  /data/app/~~KcRhAtDu_ohUoG7_ckyt2Q==/games.spearmint.matchanimal-Yg0b8aD7s5klY_lpCbdbfA==/split_config.arm64_v8a.apk!libc++_shared.so (abort_message+76)
  #02  pc 0x00000000000d2180  /data/app/~~KcRhAtDu_ohUoG7_ckyt2Q==/games.spearmint.matchanimal-Yg0b8aD7s5klY_lpCbdbfA==/split_config.arm64_v8a.apk!libc++_shared.so (demangling_terminate_handler()+62)
  #03  pc 0x00000000000e6e80  /data/app/~~KcRhAtDu_ohUoG7_ckyt2Q==/games.spearmint.matchanimal-Yg0b8aD7s5klY_lpCbdbfA==/split_config.arm64_v8a.apk!libc++_shared.so (std::__terminate(void (*)())+59)
  #04  pc 0x00000000000e6e18  /data/app/~~KcRhAtDu_ohUoG7_ckyt2Q==/games.spearmint.matchanimal-Yg0b8aD7s5klY_lpCbdbfA==/split_config.arm64_v8a.apk!libc++_shared.so (std::terminate()+88)
  #05  pc 0x00000000000986b0  /data/app/~~KcRhAtDu_ohUoG7_ckyt2Q==/games.spearmint.matchanimal-Yg0b8aD7s5klY_lpCbdbfA==/split_config.arm64_v8a.apk!libopenal.so (alcDestroyContext+3423)
  #06  pc 0x000000000068c2b8  /data/app/~~KcRhAtDu_ohUoG7_ckyt2Q==/games.spearmint.matchanimal-Yg0b8aD7s5klY_lpCbdbfA==/split_config.arm64_v8a.apk!libMatchAnimal.so (ax::AudioEngineImpl::~AudioEngineImpl()+293)
  #07  pc 0x000000000068c4a0  /data/app/~~KcRhAtDu_ohUoG7_ckyt2Q==/games.spearmint.matchanimal-Yg0b8aD7s5klY_lpCbdbfA==/split_config.arm64_v8a.apk!libMatchAnimal.so (ax::AudioEngineImpl::~AudioEngineImpl()+280)
  #08  pc 0x00000000006868bc  /data/app/~~KcRhAtDu_ohUoG7_ckyt2Q==/games.spearmint.matchanimal-Yg0b8aD7s5klY_lpCbdbfA==/split_config.arm64_v8a.apk!libMatchAnimal.so (ax::AudioEngine::end()+147)
  #09  pc 0x000000000063bc50  /data/app/~~KcRhAtDu_ohUoG7_ckyt2Q==/games.spearmint.matchanimal-Yg0b8aD7s5klY_lpCbdbfA==/split_config.arm64_v8a.apk!libMatchAnimal.so (ax::Director::reset()+977)
  #10  pc 0x000000000063ca08  /data/app/~~KcRhAtDu_ohUoG7_ckyt2Q==/games.spearmint.matchanimal-Yg0b8aD7s5klY_lpCbdbfA==/split_config.arm64_v8a.apk!libMatchAnimal.so (ax::Director::mainLoop()+1044)
  #11  pc 0x000000000004f2e0  /data/dalvik-cache/arm64/data@app@~~KcRhAtDu_ohUoG7_ckyt2Q==@games.spearmint.matchanimal-Yg

rh101 commented 1 year ago

Was this running on a real device or emulator?

Was it connected to a debugger at the time it crashed? I've only ever seen this when running the app on a device connected to a debugger, such as what is described in #1195

If it is reproducible, then why not just put a breakpoint on ax::AudioEngine::end() and trace the execution of the code from there?

kiranb47 commented 1 year ago

Hey @rh101 The issue is not reproducible in any of our test devices. Crash logs are from Google Play live users.

aismann commented 1 year ago

The issue is not reproducible in any of our test devices. Crash logs are from Google Play live users.

Is this a sporadic issue (only some devices/users), right? Or a general issue on all same devices?

rh101 commented 1 year ago

@kiranb47 Are you by any chance calling AudioEngine::end() anywhere in your own code?

For example, in the Cocos2d CPP template, there is this section in AppDelegate.cpp:

AppDelegate::~AppDelegate() 
{
    AudioEngine::end();
}

halx99 commented 1 year ago

@kiranb47 Are you by any chance calling AudioEngine::end() anywhere in your own code?

For example, in the Cocos2d CPP template, there is this section in AppDelegate.cpp:
AppDelegate::~AppDelegate() 
{
    AudioEngine::end();
}

User don't needs to invoke AudioEngine::end, see this issue: https://github.com/axmolengine/axmol/issues/550

rh101 commented 1 year ago

I just had an idea and tested it out, and managed to reproduce this issue consistently.

1) Load the app 2) Make or receive a phone call

This causes the audio section to throw an error, which closes the stream. Audio in the app no longer works, and eventually it will crash because of 2 different issues.

One would be something like Fail to play Sounds/AudioFile.mp3 cause by limited max instance of AudioEngine OR
The other would be what is posted above by @kiranb47, which would generally happen when a user exits the app: terminating with uncaught exception of type al::backend_exception: Failed to stop stream: ErrorClosed

When I received a phone call, I saw this in logcat:

2023-05-25 16:56:35.361 25517-25533 localhost.test          com.localhost.test                D  PlayerBase::setVolume() from IPlayer
2023-05-25 16:56:35.361 25517-25533 AAudioStream            com.localhost.test                D  setDuckAndMuteVolume() to 0.000000
2023-05-25 16:56:35.361 25517-25533 AudioStrea...lay_Client com.localhost.test                D  doSetVolume() mStreamVolume * duckAndMuteVolume = 1.000000 * 0.000000 = 0.000000
2023-05-25 16:56:39.181 25517-25517 AxmolActivity           com.localhost.test                D  onPause()
2023-05-25 16:56:39.259 25517-25517 AxmolActivity           com.localhost.test                D  onWindowFocusChanged() hasFocus=false
2023-05-25 16:56:39.514 25517-25693 AudioStrea...nal_Client com.localhost.test                D  onEventFromServer - got AAUDIO_SERVICE_EVENT_STOPPED
2023-05-25 16:56:39.517 25517-25693 AAudioStream            com.localhost.test                D  setState(s#2) from 4 to 13
2023-05-25 16:56:39.517 25517-25693 AudioStrea...nal_Client com.localhost.test                W  onEventFromServer - AAUDIO_SERVICE_EVENT_DISCONNECTED - FIFO cleared
2023-05-25 16:56:39.519 25517-25693 AudioStrea...lay_Client com.localhost.test                D  callbackLoop() exiting, result = -899, isActive() = 0 <<<<<<<<<<<<<<
2023-05-25 16:56:39.522 25517-25914 OboeAudio               com.localhost.test                D  oboe_aaudio_error_thread_proc(,-899) - entering >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-05-25 16:56:39.522 25517-25914 AAudio                  com.localhost.test                D  AAudioStream_requestStop(s#2) called
2023-05-25 16:56:39.531 25517-25914 AAudioStream            com.localhost.test                D  joinThread_l() pthread_join succeeded
2023-05-25 16:56:39.531 25517-25914 IsochronousClockModel   com.localhost.test                D  stop(nanos = 15325857903817) max lateness = 74 micros
2023-05-25 16:56:39.531 25517-25914 AAudioStream            com.localhost.test                D  setState(s#2) from 13 to 9
2023-05-25 16:56:39.531 25517-25914 AAudioStream            com.localhost.test                W  setState(2) tried to set to 9 but already DISCONNECTED
2023-05-25 16:56:39.532 25517-25914 AAudio                  com.localhost.test                D  AAudioStream_requestStop(s#2) called
2023-05-25 16:56:39.532 25517-25914 AAudioStream            com.localhost.test                D  joinThread() - but has no thread or already join()ed
2023-05-25 16:56:39.532 25517-25914 AudioStrea...nal_Client com.localhost.test                W  requestStop_l() stop callback returned -895, returning early
2023-05-25 16:56:39.542 25517-25914 AAudio                  com.localhost.test                D  AAudioStream_close(s#2) called ---------------
2023-05-25 16:56:39.542 25517-25914 AudioStrea...nal_Client com.localhost.test                D  release_l(): mServiceStreamHandle = 0x00000034
2023-05-25 16:56:39.542 25517-25914 AAudioStream            com.localhost.test                D  joinThread() - but has no thread or already join()ed
2023-05-25 16:56:39.542 25517-25914 AudioStrea...nal_Client com.localhost.test                W  requestStop_l() stop callback returned -895, returning early
2023-05-25 16:56:39.542 25517-25914 AAudioStream            com.localhost.test                D  setState(s#2) from 13 to 11
2023-05-25 16:56:39.645 25517-25914 AAudioStream            com.localhost.test                D  setState(s#2) from 11 to 11
2023-05-25 16:56:39.645 25517-25914 AAudioStream            com.localhost.test                D  setState(s#2) from 11 to 12
2023-05-25 16:56:39.645 25517-25914 AudioStrea...nal_Client com.localhost.test                D  ~AudioStreamInternal() 0xb400007a7a173c80 called
2023-05-25 16:56:39.645 25517-25914 AAudioStream            com.localhost.test                D  ~AudioStream(s#2) mPlayerBase strongCount = 2
2023-05-25 16:56:39.645 25517-25914 AAudio                  com.localhost.test                D  AAudioStream_close(s#2) returned 0 ---------
2023-05-25 16:56:39.645 25517-25914 OboeAudio               com.localhost.test                D  oboe_aaudio_error_thread_proc() - exiting <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-05-25 16:56:41.255 25517-25890 FA                      com.localhost.test                I  Application backgrounded at: timestamp_millis: 1684997799249
2023-05-25 16:56:42.911 25517-25517 AxmolActivity           com.localhost.test                D  onResume()
2023-05-25 16:56:42.933 25517-25658 OpenGLRenderer          com.localhost.test                E  Unable to match the desired swap behavior.
2023-05-25 16:56:42.937 25517-25675 GLSurfaceView           com.localhost.test                W  Warning, !readyToDraw() but waiting for draw finished! Early reporting draw finished.
2023-05-25 16:56:42.969 25517-25517 AxmolActivity           com.localhost.test                D  onWindowFocusChanged() hasFocus=true

oboe_aaudio_error_thread_proc() was definitely called there, which closes the stream.

@halx99 This shouldn't be happening, right? I've never tested this scenario before, but this causes the same issue described in #1195

kiranb47 commented 1 year ago

@rh101 @halx99 We are not invoking AudioEngine::end()

kiranb47 commented 1 year ago

@aismann 5.2% users affected

halx99 commented 1 year ago

I create a PR to switch default audio backend to opensl, plz update and check.

rh101 commented 1 year ago

I create a PR to switch default audio backend to opensl, plz update and check.

I'll merge the PR in locally and test it now

rh101 commented 1 year ago

@halx99 Using OpenSL, everything is working fine, with no errors or crashes at all. Making and receiving phone calls resulted in this logcat output, which looks normal, with no errors:

2023-05-25 18:37:37.477  6655-6859  localhost.test          com.localhost.test                D  PlayerBase::setVolume() from IPlayer
2023-05-25 18:37:42.083  6655-6655  AxmolActivity           com.localhost.test                D  onPause()
2023-05-25 18:37:42.117  6655-6655  AxmolActivity           com.localhost.test                D  onWindowFocusChanged() hasFocus=false
2023-05-25 18:37:44.167  6655-7826  FA                      com.localhost.test                I  Application backgrounded at: timestamp_millis: 1685003862161
2023-05-25 18:37:44.623  6655-6655  AxmolActivity           com.localhost.test                D  onResume()
2023-05-25 18:37:44.649  6655-6847  OpenGLRenderer          com.localhost.test                E  Unable to match the desired swap behavior.
2023-05-25 18:37:44.651  6655-6857  GLSurfaceView           com.localhost.test                W  Warning, !readyToDraw() but waiting for draw finished! Early reporting draw finished.
2023-05-25 18:37:44.651  6655-6655  SurfaceSyncer           com.localhost.test                E  Failed to find sync for id=1
2023-05-25 18:37:44.678  6655-6655  AxmolActivity           com.localhost.test                D  onWindowFocusChanged() hasFocus=true
2023-05-25 18:37:45.746  6655-6859  localhost.test          com.localhost.test                D  PlayerBase::setVolume() from IPlayer

The app audio worked fine after the phone call terminated. Also, no more audio issues or crashes when using a debugger and breakpoints as described in #1195.

halx99 commented 1 year ago

@rh101 thanks for you test, merged

rh101 commented 1 year ago

@rh101 thanks for you test, merged

You're welcome. I hope that the issue @kiranb47 is having is related to this, and that this solution solves it too.

halx99 commented 1 year ago

refer to https://chromium.googlesource.com/external/github.com/google/oboe/+/refs/tags/1.5.0/docs/OpenSLESMigration.md#stream-disconnection, the oboe with aaudio backend support stream disconnect(require recreate stream after handphone call). that's why opensl no this issue, maybe openal-soft not handle properly.

rh101 commented 1 year ago

the oboe with aaudio backend support stream disconnect(require recreate stream after handphone call). that's why opensl no this issue, maybe openal-soft not handle properly.

Fair enough. Would it be beneficial to eventually re-enable OBOE in the future and add support for recreating the stream on any error conditions? Using OpenSL right now is the right move to prevent the crashes, but I'm not sure if anyone requires the extra functionality available with OBOE, so I can't comment on that.

halx99 commented 1 year ago

I think opensl is enough, but I also create a bugfix PR for openal-soft: https://github.com/kcat/openal-soft/pull/848

kiranb47 commented 1 year ago

@halx99 @rh101 @aismann Issue is now resolved after i changed to OpenSL. Thank you for the PR.

axmolengine / axmol

Android Crash 2 #1212