Error in Android -> E/AAudioStream: setState(3) tried to set to 11 but already CLOSING

sviudes · July 1, 2021, 9:46am

I’ve just updated to FMOD 2.01.10 from 1.10.20, and while playing a sound sometimes it stutters and logcat shows the text I’m pasting below. Any idea? It was working fine for several years until I updated to FMOD 2:

2021-07-01 11:32:43.218 25729-25984/mypkg D/AAudio: AAudioStream_requestStop(s#3) called
2021-07-01 11:32:43.218 25729-26212/mypkg D/AudioStreamInternalPlay_Client: callbackLoop() exiting, result = 96, isActive() = 1 <<<<<<<<<<<<<<
2021-07-01 11:32:43.219 25729-25984/mypkg D/IsochronousClockModel: stop(nanos = 588397943124383) max lateness = 96 micros
2021-07-01 11:32:43.219 25729-25984/mypkg D/AAudioStream: setState(s#3) from 4 to 9
2021-07-01 11:32:43.282 25729-25984/mypkg D/mypkg: PlayerBase::stop() from IPlayer
2021-07-01 11:32:43.282 25729-26208/mypkg I/fmod: Thread::callback : FMOD mixer thread finished.
2021-07-01 11:32:43.283 25729-25984/mypkg D/AAudio: AAudioStream_close(s#3) called ---------------
2021-07-01 11:32:43.283 25729-25984/mypkg D/AAudioStream: setState(s#3) from 9 to 11
2021-07-01 11:32:43.385 25729-25984/mypkg D/AAudioStream: setState(s#3) from 11 to 11
2021-07-01 11:32:43.385 25729-25984/mypkg E/AAudioStream: setState(3) tried to set to 11 but already CLOSING
2021-07-01 11:32:43.385 25729-25984/mypkg D/AAudioStream: setState(s#3) from 11 to 12
2021-07-01 11:32:43.385 25729-25984/mypkg D/AAudioStream: ~AudioStream(s#3) mPlayerBase strongCount = 2
2021-07-01 11:32:43.385 25729-25984/mypkg D/AAudio: AAudioStream_close(s#3) returned 0 ---------
2021-07-01 11:32:43.386 25729-25984/mypkg I/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2021-07-01 11:32:43.387 25729-25984/mypkg I/AudioStreamBuilder: rate = 0, channels = 0, format = 0, sharing = SH, dir = OUTPUT
2021-07-01 11:32:43.387 25729-25984/mypkg I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: OFF with frames = 0
2021-07-01 11:32:43.387 25729-25984/mypkg I/AudioStreamBuilder: usage = 14, contentType = 0, inputPreset = 0, allowedCapturePolicy = 0
2021-07-01 11:32:43.387 25729-25984/mypkg I/AudioStreamBuilder: privacy sensitive = false
2021-07-01 11:32:43.387 25729-25984/mypkg D/mypkg: PlayerBase::PlayerBase()
2021-07-01 11:32:43.407 25729-25984/mypkg D/AudioStreamInternal_Client: open() original HW burst = 96, minMicros = 2000 => SW burst = 96
2021-07-01 11:32:43.407 25729-25984/mypkg D/AAudioStream: setState(s#4) from 0 to 2
2021-07-01 11:32:43.408 25729-25984/mypkg I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#4 ----------------
2021-07-01 11:32:43.408 25729-25984/mypkg D/AAudio: AAudioStream_close(s#4) called ---------------
2021-07-01 11:32:43.408 25729-25984/mypkg D/AAudioStream: setState(s#4) from 2 to 11
2021-07-01 11:32:43.511 25729-25984/mypkg D/AAudioStream: setState(s#4) from 11 to 11
2021-07-01 11:32:43.511 25729-25984/mypkg E/AAudioStream: setState(4) tried to set to 11 but already CLOSING
2021-07-01 11:32:43.511 25729-25984/mypkg D/AAudioStream: setState(s#4) from 11 to 12
2021-07-01 11:32:43.511 25729-25984/mypkg D/AAudioStream: ~AudioStream(s#4) mPlayerBase strongCount = 2
2021-07-01 11:32:43.511 25729-25984/mypkg D/AAudio: AAudioStream_close(s#4) returned 0 ---------
2021-07-01 11:32:43.513 25729-25984/mypkg I/fmod: FMOD::supportsLowLatency : Low latency = true, Pro Audio = true, Bluetooth On = false, Acceptable Block Size = true (96)
2021-07-01 11:32:43.513 25729-25984/mypkg I/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2021-07-01 11:32:43.513 25729-25984/mypkg I/AudioStreamBuilder: rate = 0, channels = 0, format = 0, sharing = SH, dir = OUTPUT
2021-07-01 11:32:43.513 25729-25984/mypkg I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: ON with frames = 0
2021-07-01 11:32:43.513 25729-25984/mypkg I/AudioStreamBuilder: usage = 14, contentType = 0, inputPreset = 0, allowedCapturePolicy = 0
2021-07-01 11:32:43.513 25729-25984/mypkg I/AudioStreamBuilder: privacy sensitive = false
2021-07-01 11:32:43.514 25729-25984/mypkg D/mypkg: PlayerBase::PlayerBase()
2021-07-01 11:32:43.530 25729-25984/mypkg D/AudioStreamInternal_Client: open() original HW burst = 96, minMicros = 2000 => SW burst = 96
2021-07-01 11:32:43.530 25729-25984/mypkg D/AAudioStream: setState(s#5) from 0 to 2
2021-07-01 11:32:43.532 25729-25984/mypkg I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#5 ----------------
2021-07-01 11:32:43.532 25729-25984/mypkg D/AAudio: AAudioStream_close(s#5) called ---------------
2021-07-01 11:32:43.532 25729-25984/mypkg D/AAudioStream: setState(s#5) from 2 to 11
2021-07-01 11:32:43.634 25729-25984/mypkg D/AAudioStream: setState(s#5) from 11 to 11
2021-07-01 11:32:43.634 25729-25984/mypkg E/AAudioStream: setState(5) tried to set to 11 but already CLOSING
2021-07-01 11:32:43.634 25729-25984/mypkg D/AAudioStream: setState(s#5) from 11 to 12
2021-07-01 11:32:43.634 25729-25984/mypkg D/AAudioStream: ~AudioStream(s#5) mPlayerBase strongCount = 2
2021-07-01 11:32:43.634 25729-25984/mypkg D/AAudio: AAudioStream_close(s#5) returned 0 ---------
2021-07-01 11:32:43.634 25729-25984/mypkg I/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2021-07-01 11:32:43.634 25729-25984/mypkg I/AudioStreamBuilder: rate = 0, channels = 0, format = 0, sharing = SH, dir = OUTPUT
2021-07-01 11:32:43.634 25729-25984/mypkg I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: ON with frames = 0
2021-07-01 11:32:43.634 25729-25984/mypkg I/AudioStreamBuilder: usage = 14, contentType = 0, inputPreset = 0, allowedCapturePolicy = 0
2021-07-01 11:32:43.634 25729-25984/mypkg I/AudioStreamBuilder: privacy sensitive = false
2021-07-01 11:32:43.634 25729-25984/mypkg D/mypkg: PlayerBase::PlayerBase()
2021-07-01 11:32:43.654 25729-25984/mypkg D/AudioStreamInternal_Client: open() original HW burst = 96, minMicros = 2000 => SW burst = 96
2021-07-01 11:32:43.654 25729-25984/mypkg D/AAudioStream: setState(s#6) from 0 to 2
2021-07-01 11:32:43.655 25729-25984/mypkg I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#6 ----------------
2021-07-01 11:32:43.657 25729-25984/mypkg I/fmod: OutputAAudio::init : Sample rate: HW = 48000, SW = 24000 Block size: HW = 96, SW = 512.
2021-07-01 11:32:43.657 25729-25984/mypkg I/fmod: DownMix::init : dspbuffersize: 512 rate: 24000. output speaker mode: 3, input speaker mode 2
2021-07-01 11:32:43.657 25729-25984/mypkg I/fmod: DownMix::init : done.
2021-07-01 11:32:43.657 25729-25984/mypkg I/fmod: SystemI::startDriver : Output requires a sample rate of 48000Hz, resampling will occur.
2021-07-01 11:32:43.657 25729-25984/mypkg I/fmod: Thread::initThread : Init FMOD mixer thread. Affinity: 0x8000000000000001, Priority: 0xFFFF7FFA, Stack Size: 81920, Semaphore: Yes, Sleep Time: 0, Looping: Yes.
2021-07-01 11:32:43.658 25729-25984/mypkg D/AAudio: AAudioStream_requestStart(s#6) called --------------
2021-07-01 11:32:43.658 25729-25984/mypkg D/AAudioStream: setState(s#6) from 2 to 3
2021-07-01 11:32:43.760 25729-25984/mypkg D/mypkg: PlayerBase::start() from IPlayer
2021-07-01 11:32:43.761 25729-25984/mypkg D/AAudio: AAudioStream_requestStart(s#6) returned 0 ---------
2021-07-01 11:32:43.763 25729-26313/mypkg D/AudioStreamInternalPlay_Client: callbackLoop() entering >>>>>>>>>>>>>>>
2021-07-01 11:32:43.763 25729-26313/mypkg D/AudioStreamInternal_Client: onEventFromServer - got AAUDIO_SERVICE_EVENT_STARTED
2021-07-01 11:32:43.763 25729-26313/mypkg D/AAudioStream: setState(s#6) from 3 to 4
2021-07-01 11:32:44.846 25729-25984/mypkg D/AAudio: AAudioStream_requestStop(s#6) called
2021-07-01 11:32:44.846 25729-26313/mypkg D/AudioStreamInternalPlay_Client: callbackLoop() exiting, result = 96, isActive() = 1 <<<<<<<<<<<<<<
2021-07-01 11:32:44.846 25729-25984/mypkg D/IsochronousClockModel: stop(nanos = 588399570961316) max lateness = 75 micros
2021-07-01 11:32:44.846 25729-25984/mypkg D/AAudioStream: setState(s#6) from 4 to 9
2021-07-01 11:32:44.954 25729-25984/mypkg D/mypkg: PlayerBase::stop() from IPlayer
2021-07-01 11:32:44.955 25729-26309/mypkg I/fmod: Thread::callback : FMOD mixer thread finished.
2021-07-01 11:32:44.955 25729-25984/mypkg D/AAudio: AAudioStream_close(s#6) called ---------------
2021-07-01 11:32:44.956 25729-25984/mypkg D/AAudioStream: setState(s#6) from 9 to 11
2021-07-01 11:32:45.059 25729-25984/mypkg D/AAudioStream: setState(s#6) from 11 to 11
2021-07-01 11:32:45.059 25729-25984/mypkg E/AAudioStream: setState(6) tried to set to 11 but already CLOSING
2021-07-01 11:32:45.059 25729-25984/mypkg D/AAudioStream: setState(s#6) from 11 to 12
2021-07-01 11:32:45.059 25729-25984/mypkg D/AAudioStream: ~AudioStream(s#6) mPlayerBase strongCount = 2
2021-07-01 11:32:45.059 25729-25984/mypkg D/AAudio: AAudioStream_close(s#6) returned 0 ---------
2021-07-01 11:32:45.060 25729-25984/mypkg I/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2021-07-01 11:32:45.060 25729-25984/mypkg I/AudioStreamBuilder: rate = 0, channels = 0, format = 0, sharing = SH, dir = OUTPUT
2021-07-01 11:32:45.060 25729-25984/mypkg I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: OFF with frames = 0
2021-07-01 11:32:45.060 25729-25984/mypkg I/AudioStreamBuilder: usage = 14, contentType = 0, inputPreset = 0, allowedCapturePolicy = 0
2021-07-01 11:32:45.060 25729-25984/mypkg I/AudioStreamBuilder: privacy sensitive = false
2021-07-01 11:32:45.060 25729-25984/mypkg D/mypkg: PlayerBase::PlayerBase()
2021-07-01 11:32:45.081 25729-25984/mypkg D/AudioStreamInternal_Client: open() original HW burst = 96, minMicros = 2000 => SW burst = 96
2021-07-01 11:32:45.081 25729-25984/mypkg D/AAudioStream: setState(s#7) from 0 to 2
2021-07-01 11:32:45.082 25729-25984/mypkg I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#7 ----------------
2021-07-01 11:32:45.082 25729-25984/mypkg D/AAudio: AAudioStream_close(s#7) called ---------------
2021-07-01 11:32:45.082 25729-25984/mypkg D/AAudioStream: setState(s#7) from 2 to 11
2021-07-01 11:32:45.185 25729-25984/mypkg D/AAudioStream: setState(s#7) from 11 to 11
2021-07-01 11:32:45.185 25729-25984/mypkg E/AAudioStream: setState(7) tried to set to 11 but already CLOSING
2021-07-01 11:32:45.185 25729-25984/mypkg D/AAudioStream: setState(s#7) from 11 to 12
2021-07-01 11:32:45.185 25729-25984/mypkg D/AAudioStream: ~AudioStream(s#7) mPlayerBase strongCount = 2
2021-07-01 11:32:45.185 25729-25984/mypkg D/AAudio: AAudioStream_close(s#7) returned 0 ---------
2021-07-01 11:32:45.188 25729-25984/mypkg I/fmod: FMOD::supportsLowLatency : Low latency = true, Pro Audio = true, Bluetooth On = false, Acceptable Block Size = true (96)
2021-07-01 11:32:45.188 25729-25984/mypkg I/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2021-07-01 11:32:45.188 25729-25984/mypkg I/AudioStreamBuilder: rate = 0, channels = 0, format = 0, sharing = SH, dir = OUTPUT
2021-07-01 11:32:45.188 25729-25984/mypkg I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: ON with frames = 0
2021-07-01 11:32:45.188 25729-25984/mypkg I/AudioStreamBuilder: usage = 14, contentType = 0, inputPreset = 0, allowedCapturePolicy = 0
2021-07-01 11:32:45.188 25729-25984/mypkg I/AudioStreamBuilder: privacy sensitive = false
2021-07-01 11:32:45.188 25729-25984/mypkg D/mypkg: PlayerBase::PlayerBase()
2021-07-01 11:32:45.203 25729-25984/mypkg D/AudioStreamInternal_Client: open() original HW burst = 96, minMicros = 2000 => SW burst = 96
2021-07-01 11:32:45.203 25729-25984/mypkg D/AAudioStream: setState(s#8) from 0 to 2
2021-07-01 11:32:45.205 25729-25984/mypkg I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#8 ----------------
2021-07-01 11:32:45.205 25729-25984/mypkg D/AAudio: AAudioStream_close(s#8) called ---------------
2021-07-01 11:32:45.205 25729-25984/mypkg D/AAudioStream: setState(s#8) from 2 to 11
2021-07-01 11:32:45.307 25729-25984/mypkg D/AAudioStream: setState(s#8) from 11 to 11
2021-07-01 11:32:45.307 25729-25984/mypkg E/AAudioStream: setState(8) tried to set to 11 but already CLOSING
2021-07-01 11:32:45.307 25729-25984/mypkg D/AAudioStream: setState(s#8) from 11 to 12
2021-07-01 11:32:45.307 25729-25984/mypkg D/AAudioStream: ~AudioStream(s#8) mPlayerBase strongCount = 2
2021-07-01 11:32:45.307 25729-25984/mypkg D/AAudio: AAudioStream_close(s#8) returned 0 ---------
2021-07-01 11:32:45.307 25729-25984/mypkg I/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2021-07-01 11:32:45.307 25729-25984/mypkg I/AudioStreamBuilder: rate = 0, channels = 0, format = 0, sharing = SH, dir = OUTPUT
2021-07-01 11:32:45.307 25729-25984/mypkg I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: ON with frames = 0
2021-07-01 11:32:45.307 25729-25984/mypkg I/AudioStreamBuilder: usage = 14, contentType = 0, inputPreset = 0, allowedCapturePolicy = 0
2021-07-01 11:32:45.307 25729-25984/mypkg I/AudioStreamBuilder: privacy sensitive = false
2021-07-01 11:32:45.307 25729-25984/mypkg D/mypkg: PlayerBase::PlayerBase()
2021-07-01 11:32:45.324 25729-25984/mypkg D/AudioStreamInternal_Client: open() original HW burst = 96, minMicros = 2000 => SW burst = 96
2021-07-01 11:32:45.324 25729-25984/mypkg D/AAudioStream: setState(s#9) from 0 to 2
2021-07-01 11:32:45.325 25729-25984/mypkg I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#9 ----------------
2021-07-01 11:32:45.328 25729-25984/mypkg I/fmod: OutputAAudio::init : Sample rate: HW = 48000, SW = 24000 Block size: HW = 96, SW = 512.
2021-07-01 11:32:45.328 25729-25984/mypkg I/fmod: DownMix::init : dspbuffersize: 512 rate: 24000. output speaker mode: 3, input speaker mode 2
2021-07-01 11:32:45.328 25729-25984/mypkg I/fmod: DownMix::init : done.
2021-07-01 11:32:45.328 25729-25984/mypkg I/fmod: SystemI::startDriver : Output requires a sample rate of 48000Hz, resampling will occur.
2021-07-01 11:32:45.328 25729-25984/mypkg I/fmod: Thread::initThread : Init FMOD mixer thread. Affinity: 0x8000000000000001, Priority: 0xFFFF7FFA, Stack Size: 81920, Semaphore: Yes, Sleep Time: 0, Looping: Yes.
2021-07-01 11:32:45.328 25729-25984/mypkg D/AAudio: AAudioStream_requestStart(s#9) called --------------
2021-07-01 11:32:45.328 25729-25984/mypkg D/AAudioStream: setState(s#9) from 2 to 3
2021-07-01 11:32:45.430 25729-25984/mypkg D/mypkg: PlayerBase::start() from IPlayer
2021-07-01 11:32:45.430 25729-25984/mypkg D/AAudio: AAudioStream_requestStart(s#9) returned 0 ---------
2021-07-01 11:32:45.431 25729-26330/mypkg D/AudioStreamInternalPlay_Client: callbackLoop() entering >>>>>>>>>>>>>>>
2021-07-01 11:32:45.431 25729-26330/mypkg D/AudioStreamInternal_Client: onEventFromServer - got AAUDIO_SERVICE_EVENT_STARTED
2021-07-01 11:32:45.431 25729-26330/mypkg D/AAudioStream: setState(s#9) from 3 to 4

tristanjl · July 1, 2021, 11:18pm

Hi sviudes,

Which device are you seeing this on?

So the setState calls are AAudio internal calls, so they would be based on the OS implementation. The already closing message is most likely from the call - setState(s#5) from 11 to 11 - failing to change the state.

In the log, you can see a series of :
AAudioStream_close
AAudioStreamBuilder_openStream
AAudioStream_close
AAudioStreamBuilder_openStream
AAudioStream_close
AAudioStreamBuilder_openStream
AAudioStream_requestStart
And that is repeated. The first calls to open/close stream, FMOD uses to gather information about the audio device. The last call before request start is to open the audio device stream before starting it for device playback.

The reason it is repeated happens either because the stream encounters an error (eg bluetooth headphones disconnected while playing out of them) or FMOD detects a change with the headphone jack (there is a separate check for this as some android devices do not invalidate the stream when unplugging headphones).

If the device has to restart the audio output device, that would lead to a brief stutter. So as long as its happening for a valid reason (eg bluetooth headphones connecting/disconnecting), its reasonable to expect this. Can you check for any cause that might be along these lines?

sviudes · July 5, 2021, 5:14pm

I’m using a Google Pixel 5. While testing no changes were done (no headphones or bluetooth devices connected / disconnected). If I can help by testing anything on my Pixel 5, just tell me and I’ll do it.

tristanjl · July 7, 2021, 6:06am

Hmm, that is unusual. We haven’t seen any issues previously with any pixel devices - typically we have encountered unusual stuttering on other handsets and have been unable to reproduce anything similar on Pixel devices. Will have to run through a few things to narrow it down:

Are you changing the dsp buffer size or count?
If you run oboe tester, can you reproduce this issue with any combination of settings?
Is this android 11?
If you change the output mode to openSL, do you see the same issue?

sviudes · July 7, 2021, 10:00am

- Are you changing the dsp buffer size or count?
No, I’m using defaults. I see that buffer length is 512 and there are 4 buffers.

- If you run oboe tester, can you reproduce this issue with any combination of settings?
With default settings, I get “setState(n) tried to set to 11 but already CLOSING” error message only when I touch “open” button.

- Is this android 11?
Yes

- If you change the output mode to openSL, do you see the same issue?
It happens when using FMOD_OUTPUTTYPE_AUTODETECT or FMOD_OUTPUTTYPE_AAUDIO.
Using OpenSL I don’t see the same issue! Using AudioTrack works fine too.

Please let me know if you want more testing. Thank you.

tristanjl · July 8, 2021, 6:44am

So a fallback option would be to set the output mode to OpenSL - this is the output mode that would have been used for 1.10. Normally with AAudio issues, they have been bugs with the handset OS level. So there are some extra things to test:

Do the audio glitches happen if wifi is disabled?
How often do the audio glitches happen with FMOD?
With the oboe tester, can you run the auto glitch test and send us the log output? Ideally needs to be run in a quiet environment as it uses the phones microphone to check.

sviudes · July 13, 2021, 1:40pm

Sorry for the late reply.

Yes, the glitches happen if WiFi is disabled. The glitches happens so frequently.

Here is the auto glitch test result:

=== STARTED at Tue Jul 13 15:35:40 GMT+02:00 2021
AutoGlitch
OboeTester (47) v 1.6.5, Oboe v 1.6.0
Google, Pixel 5, redfin
RQ3A.210605.005
========================== #1
Requested:
INP-M, ID = 0, SR = 0, Perf = LL, EX, ch = 0/1
OUT-M, ID = 0, SR = 0, Perf = LL, EX, ch = 0/2
Actual:
INP-M, ID = 20, SR = 48000, Perf = LL, EX, ch = 0/1
OUT-M, ID = 4, SR = 48000, Perf = LL, EX, ch = 0/2
Result:
#glitches = 0, #resets = 5, max no glitch = 10.008 secs
SNR = 47,3 db, #locked = 465023, xruns = 0/0, PASS
========================== #2
Requested:
INP-M, ID = 0, SR = 0, Perf = LL, EX, ch = 0/2
OUT-M, ID = 0, SR = 0, Perf = LL, EX, ch = 0/1
Actual:
INP-M, ID = 20, SR = 48000, Perf = LL, EX, ch = 0/2
OUT-M, ID = 4, SR = 48000, Perf = LL, EX, ch = 0/1
Result:
#glitches = 0, #resets = 6, max no glitch = 9.991 secs
SNR = 41,1 db, #locked = 464291, xruns = 0/0, PASS
========================== #3
Requested:
INP-M, ID = 0, SR = 48000, Perf = LL, SH, ch = 0/1
OUT-M, ID = 0, SR = 48000, Perf = LL, SH, ch = 0/2
Actual:
INP-M, ID = 20, SR = 48000, Perf = LL, SH, ch = 0/1
OUT-M, ID = 4, SR = 48000, Perf = LL, SH, ch = 0/2
Result:
#glitches = 0, #resets = 7, max no glitch = 9.997 secs
SNR = 66,6 db, #locked = 464159, xruns = 72/0, PASS
========================== #4
Requested:
INP-M, ID = 0, SR = 48000, Perf = LL, SH, ch = 0/2
OUT-M, ID = 0, SR = 48000, Perf = LL, SH, ch = 0/1
Actual:
INP-M, ID = 20, SR = 48000, Perf = LL, SH, ch = 0/2
OUT-M, ID = 4, SR = 48000, Perf = LL, SH, ch = 0/1
Result:
#glitches = 0, #resets = 8, max no glitch = 9.949 secs
SNR = 42,6 db, #locked = 461855, xruns = 70/0, PASS
========================== #5
Requested:
INP-M, ID = 0, SR = 44100, Perf = LL, SH, ch = 0/1
OUT-M, ID = 0, SR = 44100, Perf = LL, SH, ch = 0/2
Actual:
INP-L, ID = 20, SR = 44100, Perf = NO, SH, ch = 0/1
OUT-L, ID = 4, SR = 44100, Perf = NO, SH, ch = 0/2
Result:
#glitches = 0, #resets = 9, max no glitch = 9.951 secs
SNR = 57,0 db, #locked = 395534, xruns = 0/0, PASS
========================== #6
Requested:
INP-M, ID = 0, SR = 44100, Perf = LL, SH, ch = 0/2
OUT-M, ID = 0, SR = 44100, Perf = LL, SH, ch = 0/1
Actual:
INP-L, ID = 20, SR = 44100, Perf = NO, SH, ch = 0/2
OUT-L, ID = 4, SR = 44100, Perf = NO, SH, ch = 0/1
Result:
#glitches = 0, #resets = 10, max no glitch = 10.023 secs
SNR = 40,1 db, #locked = 403775, xruns = 0/0, PASS
========================== #7
Requested:
INP-M, ID = 0, SR = 16000, Perf = LL, SH, ch = 0/1
OUT-M, ID = 0, SR = 16000, Perf = LL, SH, ch = 0/2
Actual:
INP-L, ID = 20, SR = 16000, Perf = NO, SH, ch = 0/1
OUT-L, ID = 4, SR = 16000, Perf = NO, SH, ch = 0/2
Result:
#glitches = 0, #resets = 11, max no glitch = 10.006 secs
SNR = 74,6 db, #locked = 139907, xruns = 0/0, PASS
========================== #8
Requested:
INP-M, ID = 0, SR = 16000, Perf = LL, SH, ch = 0/2
OUT-M, ID = 0, SR = 16000, Perf = LL, SH, ch = 0/1
Actual:
INP-L, ID = 20, SR = 16000, Perf = NO, SH, ch = 0/2
OUT-L, ID = 4, SR = 16000, Perf = NO, SH, ch = 0/1
Result:
#glitches = 1, #resets = 12, max no glitch = 8.568 secs
SNR = 43,7 db, #locked = 138550, xruns = 0/0, PASS
========================== #9
Requested:
INP-M, ID = 0, SR = 48000, Perf = NO, SH, ch = 0/1
OUT-M, ID = 0, SR = 48000, Perf = NO, SH, ch = 0/2
Actual:
INP-L, ID = 20, SR = 48000, Perf = NO, SH, ch = 0/1
OUT-L, ID = 4, SR = 48000, Perf = NO, SH, ch = 0/2
Result:
#glitches = 1, #resets = 13, max no glitch = 8.652 secs
SNR = 37,8 db, #locked = 417854, xruns = 0/0, PASS
========================== #10
Requested:
INP-M, ID = 0, SR = 48000, Perf = NO, SH, ch = 0/2
OUT-M, ID = 0, SR = 48000, Perf = NO, SH, ch = 0/1
Actual:
INP-L, ID = 20, SR = 48000, Perf = NO, SH, ch = 0/2
OUT-L, ID = 4, SR = 48000, Perf = NO, SH, ch = 0/1
Result:
#glitches = 1, #resets = 14, max no glitch = 8.614 secs
SNR = 36,1 db, #locked = 416212, xruns = 0/0, PASS
========================== #11
Requested:
INP-M, ID = 0, SR = 44100, Perf = NO, SH, ch = 0/1
OUT-M, ID = 0, SR = 44100,

Perf = NO, SH, ch = 0/2
Actual:
INP-L, ID = 20, SR = 44100, Perf = NO, SH, ch = 0/1
OUT-L, ID = 4, SR = 44100, Perf = NO, SH, ch = 0/2
Result:
#glitches = 0, #resets = 15, max no glitch = 9.943 secs
SNR = 43,8 db, #locked = 378688, xruns = 0/0, PASS
========================== #12
Requested:
INP-M, ID = 0, SR = 44100, Perf = NO, SH, ch = 0/2
OUT-M, ID = 0, SR = 44100, Perf = NO, SH, ch = 0/1
Actual:
INP-L, ID = 20, SR = 44100, Perf = NO, SH, ch = 0/2
OUT-L, ID = 4, SR = 44100, Perf = NO, SH, ch = 0/1
Result:
#glitches = 473, #resets = 16, max no glitch = 3.6 secs
SNR = 36,2 db, #locked = 356537, xruns = 0/0, FAIL !!!, glitch
========================== #13
Requested:
INP-M, ID = 0, SR = 16000, Perf = NO, SH, ch = 0/1
OUT-M, ID = 0, SR = 16000, Perf = NO, SH, ch = 0/2
Actual:
INP-L, ID = 20, SR = 16000, Perf = NO, SH, ch = 0/1
OUT-L, ID = 4, SR = 16000, Perf = NO, SH, ch = 0/2
Result:
#glitches = 0, #resets = 17, max no glitch = 10.002 secs
SNR = 39,6 db, #locked = 134821, xruns = 0/0, PASS
========================== #14
Requested:
INP-M, ID = 0, SR = 16000, Perf = NO, SH, ch = 0/2
OUT-M, ID = 0, SR = 16000, Perf = NO, SH, ch = 0/1
Actual:
INP-L, ID = 20, SR = 16000, Perf = NO, SH, ch = 0/2
OUT-L, ID = 4, SR = 16000, Perf = NO, SH, ch = 0/1
Result:
#glitches = 0, #resets = 18, max no glitch = 9.952 secs
SNR = 44,3 db, #locked = 134553, xruns = 0/0, PASS
Tests finished without exception.

==== SUMMARY ========

These tests FAILED:
Summary
------ #12
INP-L, ID = 20, SR = 44100, Perf = NO, SH, ch = 0/2
OUT-L, ID = 4, SR = 44100, Perf = NO, SH, ch = 0/1
#glitches = 473, #resets = 16, max no glitch = 3.6 secs
SNR = 36,2 db, #locked = 356537, xruns = 0/0, FAIL !!!, glitch

13 passed. 1 failed. 0 skipped.
== FINISHED at Tue Jul 13 15:38:13 GMT+02:00 2021

tristanjl · July 15, 2021, 6:11am

The xruns in 2 of the glitch tests are slightly concerning, but we don’t initialise in the same way as that test does, so we shouldn’t encounter the same issue.

One possibility is that the timeout restart is somehow being triggered. That should only happen in the case where there is over a second delay between mixes, but it’s worth considering.

I’ve added some additional logging that will be included in the next fmod release - if you try running again with that version, once it is released, using the logging version of FMOD and send us the log, hopefully we can get to the bottom of what is happening.

sviudes · July 15, 2021, 8:47am

Thank you very much. When it’s released, I’ll capture the logs and I’ll send them to you. Will it be the version 2.01.11?

tristanjl · July 16, 2021, 7:04am

Yep, 2.01.11

tristanjl · August 2, 2021, 1:07am

Hi sviudes,

2.01.11 is out with the additional logging. Let us know when you have a chance to get a log and if it is any different.

sviudes · August 3, 2021, 10:48am

Thank you for the reminder. I included libfmodL.so instead of libfmod.so, do I need anything else to run the logging version?

Here is the log I captured. Please let me know if you need anything else.

2021-08-03 12:46:33.163 26666-26666/mypkg I/fmod: FMOD_OS_Init : Detected CPU family: 4, features: 0x7F, cores: 8.
2021-08-03 12:46:33.167 26666-26666/mypkg I/fmod: SystemI::setOutputInternal : Setting output to ‘FMOD AAudio Output’
2021-08-03 12:46:33.167 26666-26666/mypkg I/fmod: SystemI::init : Initialize version=20111 (118066), maxchannels=5, flags=0x00100000
2021-08-03 12:46:33.168 26666-26666/mypkg I/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2021-08-03 12:46:33.168 26666-26666/mypkg I/AudioStreamBuilder: rate = 0, channels = 0, format = 0, sharing = SH, dir = OUTPUT
2021-08-03 12:46:33.168 26666-26666/mypkg I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: OFF with frames = 0
2021-08-03 12:46:33.168 26666-26666/mypkg I/AudioStreamBuilder: usage = 14, contentType = 0, inputPreset = 0, allowedCapturePolicy = 0
2021-08-03 12:46:33.168 26666-26666/mypkg I/AudioStreamBuilder: privacy sensitive = false
2021-08-03 12:46:33.168 26666-26666/mypkg D/mypkg: PlayerBase::PlayerBase()
2021-08-03 12:46:33.189 26666-26666/mypkg D/AudioStreamInternal_Client: open() original HW burst = 96, minMicros = 2000 => SW burst = 96
2021-08-03 12:46:33.190 26666-26666/mypkg D/AAudioStream: setState(s#1) from 0 to 2
2021-08-03 12:46:33.192 26666-26666/mypkg I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#1 ----------------
2021-08-03 12:46:33.192 26666-26666/mypkg D/AAudio: AAudioStream_close(s#1) called ---------------
2021-08-03 12:46:33.192 26666-26666/mypkg D/AAudioStream: setState(s#1) from 2 to 11
2021-08-03 12:46:33.294 26666-26666/mypkg D/AAudioStream: setState(s#1) from 11 to 11
2021-08-03 12:46:33.294 26666-26666/mypkg E/AAudioStream: setState(1) tried to set to 11 but already CLOSING
2021-08-03 12:46:33.294 26666-26666/mypkg D/AAudioStream: setState(s#1) from 11 to 12
2021-08-03 12:46:33.294 26666-26666/mypkg D/AAudioStream: ~AudioStream(s#1) mPlayerBase strongCount = 2
2021-08-03 12:46:33.294 26666-26666/mypkg D/AAudio: AAudioStream_close(s#1) returned 0 ---------
2021-08-03 12:46:33.301 26666-26666/mypkg I/fmod: FMOD::supportsLowLatency : Low latency = true, Pro Audio = true, Bluetooth On = false, Acceptable Block Size = true (96)
2021-08-03 12:46:33.301 26666-26666/mypkg I/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2021-08-03 12:46:33.301 26666-26666/mypkg I/AudioStreamBuilder: rate = 0, channels = 0, format = 0, sharing = SH, dir = OUTPUT
2021-08-03 12:46:33.301 26666-26666/mypkg I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: ON with frames = 0
2021-08-03 12:46:33.301 26666-26666/mypkg I/AudioStreamBuilder: usage = 14, contentType = 0, inputPreset = 0, allowedCapturePolicy = 0
2021-08-03 12:46:33.301 26666-26666/mypkg I/AudioStreamBuilder: privacy sensitive = false
2021-08-03 12:46:33.301 26666-26666/mypkg D/mypkg: PlayerBase::PlayerBase()
2021-08-03 12:46:33.322 26666-26666/mypkg D/AudioStreamInternal_Client: open() original HW burst = 96, minMicros = 2000 => SW burst = 96
2021-08-03 12:46:33.322 26666-26666/mypkg D/AAudioStream: setState(s#2) from 0 to 2
2021-08-03 12:46:33.323 26666-26666/mypkg I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#2 ----------------
2021-08-03 12:46:33.323 26666-26666/mypkg D/AAudio: AAudioStream_close(s#2) called ---------------
2021-08-03 12:46:33.323 26666-26666/mypkg D/AAudioStream: setState(s#2) from 2 to 11
2021-08-03 12:46:33.425 26666-26666/mypkg D/AAudioStream: setState(s#2) from 11 to 11
2021-08-03 12:46:33.425 26666-26666/mypkg E/AAudioStream: setState(2) tried to set to 11 but already CLOSING
2021-08-03 12:46:33.425 26666-26666/mypkg D/AAudioStream: setState(s#2) from 11 to 12
2021-08-03 12:46:33.426 26666-26666/mypkg D/AAudioStream: ~AudioStream(s#2) mPlayerBase strongCount = 2
2021-08-03 12:46:33.426 26666-26666/mypkg D/AAudio: AAudioStream_close(s#2) returned 0 ---------
2021-08-03 12:46:33.426 26666-26666/mypkg I/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2021-08-03 12:46:33.426 26666-26666/mypkg I/AudioStreamBuilder: rate = 0, channels = 0, format = 0, sharing = SH, dir = OUTPUT
2021-08-03 12:46:33.426 26666-26666/mypkg I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: ON with frames = 0
2021-08-03 12:46:33.426 26666-26666/mypkg I/AudioStreamBuilder: usage = 14, contentType = 0, inputPreset = 0, allowedCapturePolicy = 0
2021-08-03 12:46:33.426 26666-26666/mypkg I/AudioStreamBuilder: privacy sensitive = false
2021-08-03 12:46:33.426 26666-26666/mypkg D/mypkg: PlayerBase::PlayerBase()
2021-08-03 12:46:33.447 26666-26666/mypkg D/AudioStreamInternal_Client: open() original HW burst = 96, minMicros = 2000 => SW burst = 96
2021-08-03 12:46:33.447 26666-26666/mypkg D/AAudioStream: setState(s#3) from 0 to 2
2021-08-03 12:46:33.449 26666-26666/mypkg I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#3 ----------------
2021-08-03 12:46:33.451 26666-26666/mypkg I/fmod: OutputAAudio::init : Sample rate: HW = 48000, SW = 24000 Block size: HW = 96, SW = 512.
2021-08-03 12:46:33.451 26666-26666/mypkg I/fmod: SystemI::init : Output requires a sample rate of 48000Hz, resampling will occur.
2021-08-03 12:46:33.452 26666-26666/mypkg I/fmod: DownMix::init : dspbuffersize: 512 rate: 24000. output speaker mode: 3, input speaker mode 2
2021-08-03 12:46:33.452 26666-26666/mypkg I/fmod: DownMix::init : done.
2021-08-03 12:46:33.452 26666-26666/mypkg I/fmod: Thread::initThread : Init FMOD stream thread. Affinity: 0x8000000000000003, Priority: 0xFFFF7FFB, Stack Size: 98304, Semaphore: No, Sleep Time: 10, Looping: Yes.
2021-08-03 12:46:33.454 26666-26666/mypkg I/fmod: Thread::initThread : Init FMOD mixer thread. Affinity: 0x8000000000000001, Priority: 0xFFFF7FFA, Stack Size: 81920, Semaphore: Yes, Sleep Time: 0, Looping: Yes.
2021-08-03 12:46:33.454 26666-26666/mypkg D/AAudio: AAudioStream_requestStart(s#3) called --------------
2021-08-03 12:46:33.454 26666-26666/mypkg D/AAudioStream: setState(s#3) from 2 to 3
2021-08-03 12:46:33.575 26666-26666/mypkg D/mypkg: PlayerBase::start() from IPlayer
2021-08-03 12:46:33.575 26666-26666/mypkg D/AAudio: AAudioStream_requestStart(s#3) returned 0 ---------
2021-08-03 12:46:33.576 26666-26666/mypkg I/fmod: SystemI::createSoundInternal : Create name=’/storage/emulated/0/Android/data/mypkg/files/.tmp/record.wav’, mode=0x00000002
2021-08-03 12:46:33.576 26666-26666/mypkg I/fmod: SystemI::createSoundInternal : Sample 0/0: name=’(null)’, format=2, channels=1, frequency=16000, lengthbytes=478676, lengthpcm=239338, pcmblocksize=0, loopstart=0, loopend=0, mode=0x00000000, channelmask=0x00000000, channelorder=0, peakvolume=0.000000.
2021-08-03 12:46:33.580 26666-26666/mypkg I/Choreographer: Skipped 39 frames! The application may be doing too much work on its main thread.
2021-08-03 12:46:33.582 26666-26843/mypkg D/AudioStreamInternalPlay_Client: callbackLoop() entering >>>>>>>>>>>>>>>
2021-08-03 12:46:33.582 26666-26843/mypkg D/AudioStreamInternal_Client: onEventFromServer - got AAUDIO_SERVICE_EVENT_STARTED
2021-08-03 12:46:33.582 26666-26843/mypkg D/AAudioStream: setState(s#3) from 3 to 4
2021-08-03 12:46:37.305 26666-26732/mypkg W/fmod: OutputAAudio::update : No mix detected for -1 ms - restarting
2021-08-03 12:46:37.305 26666-26732/mypkg D/AAudio: AAudioStream_requestStop(s#3) called
2021-08-03 12:46:37.306 26666-26843/mypkg D/AudioStreamInternalPlay_Client: callbackLoop() exiting, result = 96, isActive() = 1 <<<<<<<<<<<<<<
2021-08-03 12:46:37.306 26666-26732/mypkg D/IsochronousClockModel: stop(nanos = 559017340618936) max lateness = 53 micros
2021-08-03 12:46:37.306 26666-26732/mypkg D/AAudioStream: setState(s#3) from 4 to 9
2021-08-03 12:46:37.457 26666-26732/mypkg D/mypkg: PlayerBase::stop() from IPlayer
2021-08-03 12:46:37.458 26666-26839/mypkg I/fmod: Thread::callback : FMOD mixer thread finished.
2021-08-03 12:46:37.459 26666-26732/mypkg D/AAudio: AAudioStream_close(s#3) called ---------------
2021-08-03 12:46:37.459 26666-26732/mypkg D/AAudioStream: setState(s#3) from 9 to 11
2021-08-03 12:46:37.562 26666-26732/mypkg D/AAudioStream: setState(s#3) from 11 to 11
2021-08-03 12:46:37.562 26666-26732/mypkg E/AAudioStream: setState(3) tried to set to 11 but already CLOSING
2021-08-03 12:46:37.562 26666-26732/mypkg D/AAudioStream: setState(s#3) from 11 to 12
2021-08-03 12:46:37.562 26666-26732/mypkg D/AAudioStream: ~AudioStream(s#3) mPlayerBase strongCount = 2
2021-08-03 12:46:37.562 26666-26732/mypkg D/AAudio: AAudioStream_close(s#3) returned 0 ---------
2021-08-03 12:46:37.563 26666-26732/mypkg I/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2021-08-03 12:46:37.563 26666-26732/mypkg I/AudioStreamBuilder: rate = 0, channels = 0, format = 0, sharing = SH, dir = OUTPUT
2021-08-03 12:46:37.563 26666-26732/mypkg I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: OFF with frames = 0
2021-08-03 12:46:37.563 26666-26732/mypkg I/AudioStreamBuilder: usage = 14, contentType = 0, inputPreset = 0, allowedCapturePolicy = 0
2021-08-03 12:46:37.563 26666-26732/mypkg I/AudioStreamBuilder: privacy sensitive = false
2021-08-03 12:46:37.563 26666-26732/mypkg D/mypkg: PlayerBase::PlayerBase()
2021-08-03 12:46:37.593 26666-26732/mypkg D/AudioStreamInternal_Client: open() original HW burst = 96, minMicros = 2000 => SW burst = 96
2021-08-03 12:46:37.593 26666-26732/mypkg D/AAudioStream: setState(s#4) from 0 to 2
2021-08-03 12:46:37.594 26666-26732/mypkg I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#4 ----------------
2021-08-03 12:46:37.594 26666-26732/mypkg D/AAudio: AAudioStream_close(s#4) called ---------------
2021-08-03 12:46:37.595 26666-26732/mypkg D/AAudioStream: setState(s#4) from 2 to 11
2021-08-03 12:46:37.697 26666-26732/mypkg D/AAudioStream: setState(s#4) from 11 to 11
2021-08-03 12:46:37.697 26666-26732/mypkg E/AAudioStream: setState(4) tried to set to 11 but already CLOSING
2021-08-03 12:46:37.697 26666-26732/mypkg D/AAudioStream: setState(s#4) from 11 to 12
2021-08-03 12:46:37.697 26666-26732/mypkg D/AAudioStream: ~AudioStream(s#4) mPlayerBase strongCount = 2
2021-08-03 12:46:37.698 26666-26732/mypkg D/AAudio: AAudioStream_close(s#4) returned 0 ---------
2021-08-03 12:46:37.702 26666-26732/mypkg I/fmod: FMOD::supportsLowLatency : Low latency = true, Pro Audio = true, Bluetooth On = false, Acceptable Block Size = true (96)
2021-08-03 12:46:37.702 26666-26732/mypkg I/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2021-08-03 12:46:37.702 26666-26732/mypkg I/AudioStreamBuilder: rate = 0, channels = 0, format = 0, sharing = SH, dir = OUTPUT
2021-08-03 12:46:37.702 26666-26732/mypkg I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: ON with frames = 0
2021-08-03 12:46:37.702 26666-26732/mypkg I/AudioStreamBuilder: usage = 14, contentType = 0, inputPreset = 0, allowedCapturePolicy = 0
2021-08-03 12:46:37.702 26666-26732/mypkg I/AudioStreamBuilder: privacy sensitive = false
2021-08-03 12:46:37.702 26666-26732/mypkg D/mypkg: PlayerBase::PlayerBase()
2021-08-03 12:46:37.725 26666-26732/mypkg D/AudioStreamInternal_Client: open() original HW burst = 96, minMicros = 2000 => SW burst = 96
2021-08-03 12:46:37.725 26666-26732/mypkg D/AAudioStream: setState(s#5) from 0 to 2
2021-08-03 12:46:37.726 26666-26732/mypkg I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#5 ----------------
2021-08-03 12:46:37.726 26666-26732/mypkg D/AAudio: AAudioStream_close(s#5) called ---------------
2021-08-03 12:46:37.727 26666-26732/mypkg D/AAudioStream: setState(s#5) from 2 to 11
2021-08-03 12:46:37.830 26666-26732/mypkg D/AAudioStream: setState(s#5) from 11 to 11
2021-08-03 12:46:37.830 26666-26732/mypkg E/AAudioStream: setState(5) tried to set to 11 but already CLOSING
2021-08-03 12:46:37.830 26666-26732/mypkg D/AAudioStream: setState(s#5) from 11 to 12
2021-08-03 12:46:37.830 26666-26732/mypkg D/AAudioStream: ~AudioStream(s#5) mPlayerBase strongCount = 2
2021-08-03 12:46:37.830 26666-26732/mypkg D/AAudio: AAudioStream_close(s#5) returned 0 ---------
2021-08-03 12:46:37.830 26666-26732/mypkg I/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2021-08-03 12:46:37.831 26666-26732/mypkg I/AudioStreamBuilder: rate = 0, channels = 0, format = 0, sharing = SH, dir = OUTPUT
2021-08-03 12:46:37.831 26666-26732/mypkg I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: ON with frames = 0
2021-08-03 12:46:37.831 26666-26732/mypkg I/AudioStreamBuilder: usage = 14, contentType = 0, inputPreset = 0, allowedCapturePolicy = 0
2021-08-03 12:46:37.831 26666-26732/mypkg I/AudioStreamBuilder: privacy sensitive = false
2021-08-03 12:46:37.831 26666-26732/mypkg D/mypkg: PlayerBase::PlayerBase()
2021-08-03 12:46:37.862 26666-26732/mypkg D/AudioStreamInternal_Client: open() original HW burst = 96, minMicros = 2000 => SW burst = 96
2021-08-03 12:46:37.862 26666-26732/mypkg D/AAudioStream: setState(s#6) from 0 to 2
2021-08-03 12:46:37.863 26666-26732/mypkg I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#6 ----------------
2021-08-03 12:46:37.866 26666-26732/mypkg I/fmod: OutputAAudio::init : Sample rate: HW = 48000, SW = 24000 Block size: HW = 96, SW = 512.
2021-08-03 12:46:37.866 26666-26732/mypkg I/fmod: DownMix::init : dspbuffersize: 512 rate: 24000. output speaker mode: 3, input speaker mode 2
2021-08-03 12:46:37.866 26666-26732/mypkg I/fmod: DownMix::init : done.
2021-08-03 12:46:37.866 26666-26732/mypkg I/fmod: SystemI::startDriver : Output requires a sample rate of 48000Hz, resampling will occur.
2021-08-03 12:46:37.866 26666-26732/mypkg I/fmod: Thread::initThread : Init FMOD mixer thread. Affinity: 0x8000000000000001, Priority: 0xFFFF7FFA, Stack Size: 81920, Semaphore: Yes, Sleep Time: 0, Looping: Yes.
2021-08-03 12:46:37.867 26666-26732/mypkg D/AAudio: AAudioStream_requestStart(s#6) called --------------
2021-08-03 12:46:37.867 26666-26732/mypkg D/AAudioStream: setState(s#6) from 2 to 3
2021-08-03 12:46:37.989 26666-26732/mypkg D/mypkg: PlayerBase::start() from IPlayer
2021-08-03 12:46:37.989 26666-26732/mypkg D/AAudio: AAudioStream_requestStart(s#6) returned 0 ---------
2021-08-03 12:46:37.992 26666-26886/mypkg D/AudioStreamInternalPlay_Client: callbackLoop() entering >>>>>>>>>>>>>>>
2021-08-03 12:46:37.992 26666-26886/mypkg D/AudioStreamInternal_Client: onEventFromServer - got AAUDIO_SERVICE_EVENT_STARTED
2021-08-03 12:46:37.992 26666-26886/mypkg D/AAudioStream: setState(s#6) from 3 to 4
2021-08-03 12:46:48.545 26666-26732/mypkg W/fmod: OutputAAudio::update : No mix detected for -1 ms - restarting
2021-08-03 12:46:48.546 26666-26732/mypkg D/AAudio: AAudioStream_requestStop(s#6) called
2021-08-03 12:46:48.546 26666-26886/mypkg D/AudioStreamInternalPlay_Client: callbackLoop() exiting, result = 96, isActive() = 1 <<<<<<<<<<<<<<
2021-08-03 12:46:48.546 26666-26732/mypkg D/IsochronousClockModel: stop(nanos = 559028580411618) max lateness = 87 micros
2021-08-03 12:46:48.546 26666-26732/mypkg D/AAudioStream: setState(s#6) from 4 to 9
2021-08-03 12:46:48.687 26666-26732/mypkg D/mypkg: PlayerBase::stop() from IPlayer
2021-08-03 12:46:48.687 26666-26882/mypkg I/fmod: Thread::callback : FMOD mixer thread finished.
2021-08-03 12:46:48.689 26666-26732/mypkg D/AAudio: AAudioStream_close(s#6) called ---------------
2021-08-03 12:46:48.689 26666-26732/mypkg D/AAudioStream: setState(s#6) from 9 to 11
2021-08-03 12:46:48.793 26666-26732/mypkg D/AAudioStream: setState(s#6) from 11 to 11
2021-08-03 12:46:48.793 26666-26732/mypkg E/AAudioStream: setState(6) tried to set to 11 but already CLOSING
2021-08-03 12:46:48.793 26666-26732/mypkg D/AAudioStream: setState(s#6) from 11 to 12
2021-08-03 12:46:48.793 26666-26732/mypkg D/AAudioStream: ~AudioStream(s#6) mPlayerBase strongCount = 2
2021-08-03 12:46:48.793 26666-26732/mypkg D/AAudio: AAudioStream_close(s#6) returned 0 ---------
2021-08-03 12:46:48.795 26666-26732/mypkg I/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2021-08-03 12:46:48.796 26666-26732/mypkg I/AudioStreamBuilder: rate = 0, channels = 0, format = 0, sharing = SH, dir = OUTPUT
2021-08-03 12:46:48.796 26666-26732/mypkg I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: OFF with frames = 0
2021-08-03 12:46:48.796 26666-26732/mypkg I/AudioStreamBuilder: usage = 14, contentType = 0, inputPreset = 0, allowedCapturePolicy = 0
2021-08-03 12:46:48.796 26666-26732/mypkg I/AudioStreamBuilder: privacy sensitive = false
2021-08-03 12:46:48.796 26666-26732/mypkg D/mypkg: PlayerBase::PlayerBase()
2021-08-03 12:46:48.821 26666-26732/mypkg D/AudioStreamInternal_Client: open() original HW burst = 96, minMicros = 2000 => SW burst = 96
2021-08-03 12:46:48.821 26666-26732/mypkg D/AAudioStream: setState(s#7) from 0 to 2
2021-08-03 12:46:48.823 26666-26732/mypkg I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#7 ----------------
2021-08-03 12:46:48.823 26666-26732/mypkg D/AAudio: AAudioStream_close(s#7) called ---------------
2021-08-03 12:46:48.823 26666-26732/mypkg D/AAudioStream: setState(s#7) from 2 to 11
2021-08-03 12:46:48.928 26666-26732/mypkg D/AAudioStream: setState(s#7) from 11 to 11
2021-08-03 12:46:48.928 26666-26732/mypkg E/AAudioStream: setState(7) tried to set to 11 but already CLOSING
2021-08-03 12:46:48.928 26666-26732/mypkg D/AAudioStream: setState(s#7) from 11 to 12
2021-08-03 12:46:48.929 26666-26732/mypkg D/AAudioStream: ~AudioStream(s#7) mPlayerBase strongCount = 2
2021-08-03 12:46:48.929 26666-26732/mypkg D/AAudio: AAudioStream_close(s#7) returned 0 ---------
2021-08-03 12:46:48.932 26666-26732/mypkg I/fmod: FMOD::supportsLowLatency : Low latency = true, Pro Audio = true, Bluetooth On = false, Acceptable Block Size = true (96)
2021-08-03 12:46:48.932 26666-26732/mypkg I/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2021-08-03 12:46:48.932 26666-26732/mypkg I/AudioStreamBuilder: rate = 0, channels = 0, format = 0, sharing = SH, dir = OUTPUT
2021-08-03 12:46:48.932 26666-26732/mypkg I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: ON with frames = 0
2021-08-03 12:46:48.932 26666-26732/mypkg I/AudioStreamBuilder: usage = 14, contentType = 0, inputPreset = 0, allowedCapturePolicy = 0
2021-08-03 12:46:48.932 26666-26732/mypkg I/AudioStreamBuilder: privacy sensitive = false
2021-08-03 12:46:48.932 26666-26732/mypkg D/mypkg: PlayerBase::PlayerBase()
2021-08-03 12:46:48.959 26666-26732/mypkg D/AudioStreamInternal_Client: open() original HW burst = 96, minMicros = 2000 => SW burst = 96
2021-08-03 12:46:48.959 26666-26732/mypkg D/AAudioStream: setState(s#8) from 0 to 2
2021-08-03 12:46:48.961 26666-26732/mypkg I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#8 ----------------
2021-08-03 12:46:48.961 26666-26732/mypkg D/AAudio: AAudioStream_close(s#8) called ---------------
2021-08-03 12:46:48.961 26666-26732/mypkg D/AAudioStream: setState(s#8) from 2 to 11
2021-08-03 12:46:49.064 26666-26732/mypkg D/AAudioStream: setState(s#8) from 11 to 11
2021-08-03 12:46:49.064 26666-26732/mypkg E/AAudioStream: setState(8) tried to set to 11 but already CLOSING
2021-08-03 12:46:49.064 26666-26732/mypkg D/AAudioStream: setState(s#8) from 11 to 12
2021-08-03 12:46:49.064 26666-26732/mypkg D/AAudioStream: ~AudioStream(s#8) mPlayerBase strongCount = 2
2021-08-03 12:46:49.065 26666-26732/mypkg D/AAudio: AAudioStream_close(s#8) returned 0 ---------
2021-08-03 12:46:49.065 26666-26732/mypkg I/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2021-08-03 12:46:49.065 26666-26732/mypkg I/AudioStreamBuilder: rate = 0, channels = 0, format = 0, sharing = SH, dir = OUTPUT
2021-08-03 12:46:49.065 26666-26732/mypkg I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: ON with frames = 0
2021-08-03 12:46:49.065 26666-26732/mypkg I/AudioStreamBuilder: usage = 14, contentType = 0, inputPreset = 0, allowedCapturePolicy = 0
2021-08-03 12:46:49.065 26666-26732/mypkg I/AudioStreamBuilder: privacy sensitive = false
2021-08-03 12:46:49.065 26666-26732/mypkg D/mypkg: PlayerBase::PlayerBase()
2021-08-03 12:46:49.089 26666-26732/mypkg D/AudioStreamInternal_Client: open() original HW burst = 96, minMicros = 2000 => SW burst = 96
2021-08-03 12:46:49.089 26666-26732/mypkg D/AAudioStream: setState(s#9) from 0 to 2
2021-08-03 12:46:49.090 26666-26732/mypkg I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#9 ----------------
2021-08-03 12:46:49.092 26666-26732/mypkg I/fmod: OutputAAudio::init : Sample rate: HW = 48000, SW = 24000 Block size: HW = 96, SW = 512.
2021-08-03 12:46:49.092 26666-26732/mypkg I/fmod: DownMix::init : dspbuffersize: 512 rate: 24000. output speaker mode: 3, input speaker mode 2
2021-08-03 12:46:49.092 26666-26732/mypkg I/fmod: DownMix::init : done.
2021-08-03 12:46:49.092 26666-26732/mypkg I/fmod: SystemI::startDriver : Output requires a sample rate of 48000Hz, resampling will occur.
2021-08-03 12:46:49.093 26666-26732/mypkg I/fmod: Thread::initThread : Init FMOD mixer thread. Affinity: 0x8000000000000001, Priority: 0xFFFF7FFA, Stack Size: 81920, Semaphore: Yes, Sleep Time: 0, Looping: Yes.
2021-08-03 12:46:49.093 26666-26732/mypkg D/AAudio: AAudioStream_requestStart(s#9) called --------------
2021-08-03 12:46:49.093 26666-26732/mypkg D/AAudioStream: setState(s#9) from 2 to 3
2021-08-03 12:46:49.219 26666-26732/mypkg D/mypkg: PlayerBase::start() from IPlayer
2021-08-03 12:46:49.219 26666-26732/mypkg D/AAudio: AAudioStream_requestStart(s#9) returned 0 ---------
2021-08-03 12:46:49.226 26666-26917/mypkg D/AudioStreamInternalPlay_Client: callbackLoop() entering >>>>>>>>>>>>>>>
2021-08-03 12:46:49.226 26666-26917/mypkg D/AudioStreamInternal_Client: onEventFromServer - got AAUDIO_SERVICE_EVENT_STARTED
2021-08-03 12:46:49.226 26666-26917/mypkg D/AAudioStream: setState(s#9) from 3 to 4
2021-08-03 12:46:53.835 26666-26732/mypkg W/fmod: OutputAAudio::update : No mix detected for -2 ms - restarting
2021-08-03 12:46:53.835 26666-26732/mypkg D/AAudio: AAudioStream_requestStop(s#9) called
2021-08-03 12:46:53.836 26666-26917/mypkg D/AudioStreamInternalPlay_Client: callbackLoop() exiting, result = 96, isActive() = 1 <<<<<<<<<<<<<<
2021-08-03 12:46:53.837 26666-26732/mypkg D/IsochronousClockModel: stop(nanos = 559033871294906) max lateness = 7 micros
2021-08-03 12:46:53.837 26666-26732/mypkg D/AAudioStream: setState(s#9) from 4 to 9
2021-08-03 12:46:53.954 26666-26732/mypkg D/mypkg: PlayerBase::stop() from IPlayer
2021-08-03 12:46:53.955 26666-26913/mypkg I/fmod: Thread::callback : FMOD mixer thread finished.
2021-08-03 12:46:53.958 26666-26732/mypkg D/AAudio: AAudioStream_close(s#9) called ---------------
2021-08-03 12:46:53.958 26666-26732/mypkg D/AAudioStream: setState(s#9) from 9 to 11
2021-08-03 12:46:54.061 26666-26732/mypkg D/AAudioStream: setState(s#9) from 11 to 11
2021-08-03 12:46:54.061 26666-26732/mypkg E/AAudioStream: setState(9) tried to set to 11 but already CLOSING
2021-08-03 12:46:54.061 26666-26732/mypkg D/AAudioStream: setState(s#9) from 11 to 12
2021-08-03 12:46:54.062 26666-26732/mypkg D/AAudioStream: ~AudioStream(s#9) mPlayerBase strongCount = 2
2021-08-03 12:46:54.062 26666-26732/mypkg D/AAudio: AAudioStream_close(s#9) returned 0 ---------
2021-08-03 12:46:54.062 26666-26732/mypkg I/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2021-08-03 12:46:54.062 26666-26732/mypkg I/AudioStreamBuilder: rate = 0, channels = 0, format = 0, sharing = SH, dir = OUTPUT
2021-08-03 12:46:54.063 26666-26732/mypkg I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: OFF with frames = 0
2021-08-03 12:46:54.063 26666-26732/mypkg I/AudioStreamBuilder: usage = 14, contentType = 0, inputPreset = 0, allowedCapturePolicy = 0
2021-08-03 12:46:54.063 26666-26732/mypkg I/AudioStreamBuilder: privacy sensitive = false
2021-08-03 12:46:54.063 26666-26732/mypkg D/mypkg: PlayerBase::PlayerBase()
2021-08-03 12:46:54.092 26666-26732/mypkg D/AudioStreamInternal_Client: open() original HW burst = 96, minMicros = 2000 => SW burst = 96
2021-08-03 12:46:54.092 26666-26732/mypkg D/AAudioStream: setState(s#10) from 0 to 2
2021-08-03 12:46:54.094 26666-26732/mypkg I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#10 ----------------
2021-08-03 12:46:54.094 26666-26732/mypkg D/AAudio: AAudioStream_close(s#10) called ---------------
2021-08-03 12:46:54.094 26666-26732/mypkg D/AAudioStream: setState(s#10) from 2 to 11
2021-08-03 12:46:54.196 26666-26732/mypkg D/AAudioStream: setState(s#10) from 11 to 11
2021-08-03 12:46:54.196 26666-26732/mypkg E/AAudioStream: setState(10) tried to set to 11 but already CLOSING
2021-08-03 12:46:54.196 26666-26732/mypkg D/AAudioStream: setState(s#10) from 11 to 12
2021-08-03 12:46:54.197 26666-26732/mypkg D/AAudioStream: ~AudioStream(s#10) mPlayerBase strongCount = 2
2021-08-03 12:46:54.197 26666-26732/mypkg D/AAudio: AAudioStream_close(s#10) returned 0 ---------
2021-08-03 12:46:54.201 26666-26732/mypkg I/fmod: FMOD::supportsLowLatency : Low latency = true, Pro Audio = true, Bluetooth On = false, Acceptable Block Size = true (96)
2021-08-03 12:46:54.201 26666-26732/mypkg I/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2021-08-03 12:46:54.201 26666-26732/mypkg I/AudioStreamBuilder: rate = 0, channels = 0, format = 0, sharing = SH, dir = OUTPUT
2021-08-03 12:46:54.201 26666-26732/mypkg I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: ON with frames = 0
2021-08-03 12:46:54.201 26666-26732/mypkg I/AudioStreamBuilder: usage = 14, contentType = 0, inputPreset = 0, allowedCapturePolicy = 0
2021-08-03 12:46:54.201 26666-26732/mypkg I/AudioStreamBuilder: privacy sensitive = false
2021-08-03 12:46:54.201 26666-26732/mypkg D/mypkg: PlayerBase::PlayerBase()
2021-08-03 12:46:54.229 26666-26732/mypkg D/AudioStreamInternal_Client: open() original HW burst = 96, minMicros = 2000 => SW burst = 96
2021-08-03 12:46:54.229 26666-26732/mypkg D/AAudioStream: setState(s#11) from 0 to 2
2021-08-03 12:46:54.231 26666-26732/mypkg I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#11 ----------------
2021-08-03 12:46:54.231 26666-26732/mypkg D/AAudio: AAudioStream_close(s#11) called ---------------
2021-08-03 12:46:54.231 26666-26732/mypkg D/AAudioStream: setState(s#11) from 2 to 11
2021-08-03 12:46:54.333 26666-26732/mypkg D/AAudioStream: setState(s#11) from 11 to 11
2021-08-03 12:46:54.333 26666-26732/mypkg E/AAudioStream: setState(11) tried to set to 11 but already CLOSING
2021-08-03 12:46:54.333 26666-26732/mypkg D/AAudioStream: setState(s#11) from 11 to 12
2021-08-03 12:46:54.333 26666-26732/mypkg D/AAudioStream: ~AudioStream(s#11) mPlayerBase strongCount = 2
2021-08-03 12:46:54.333 26666-26732/mypkg D/AAudio: AAudioStream_close(s#11) returned 0 ---------
2021-08-03 12:46:54.333 26666-26732/mypkg I/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2021-08-03 12:46:54.333 26666-26732/mypkg I/AudioStreamBuilder: rate = 0, channels = 0, format = 0, sharing = SH, dir = OUTPUT
2021-08-03 12:46:54.333 26666-26732/mypkg I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: ON with frames = 0
2021-08-03 12:46:54.333 26666-26732/mypkg I/AudioStreamBuilder: usage = 14, contentType = 0, inputPreset = 0, allowedCapturePolicy = 0
2021-08-03 12:46:54.333 26666-26732/mypkg I/AudioStreamBuilder: privacy sensitive = false
2021-08-03 12:46:54.333 26666-26732/mypkg D/mypkg: PlayerBase::PlayerBase()
2021-08-03 12:46:54.362 26666-26732/mypkg D/AudioStreamInternal_Client: open() original HW burst = 96, minMicros = 2000 => SW burst = 96
2021-08-03 12:46:54.362 26666-26732/mypkg D/AAudioStream: setState(s#12) from 0 to 2
2021-08-03 12:46:54.364 26666-26732/mypkg I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#12 ----------------
2021-08-03 12:46:54.366 26666-26732/mypkg I/fmod: OutputAAudio::init : Sample rate: HW = 48000, SW = 24000 Block size: HW = 96, SW = 512.
2021-08-03 12:46:54.366 26666-26732/mypkg I/fmod: DownMix::init : dspbuffersize: 512 rate: 24000. output speaker mode: 3, input speaker mode 2
2021-08-03 12:46:54.366 26666-26732/mypkg I/fmod: DownMix::init : done.
2021-08-03 12:46:54.366 26666-26732/mypkg I/fmod: SystemI::startDriver : Output requires a sample rate of 48000Hz, resampling will occur.
2021-08-03 12:46:54.366 26666-26732/mypkg I/fmod: Thread::initThread : Init FMOD mixer thread. Affinity: 0x8000000000000001, Priority: 0xFFFF7FFA, Stack Size: 81920, Semaphore: Yes, Sleep Time: 0, Looping: Yes.
2021-08-03 12:46:54.369 26666-26732/mypkg D/AAudio: AAudioStream_requestStart(s#12) called --------------
2021-08-03 12:46:54.369 26666-26732/mypkg D/AAudioStream: setState(s#12) from 2 to 3
2021-08-03 12:46:54.487 26666-26732/mypkg D/mypkg: PlayerBase::start() from IPlayer
2021-08-03 12:46:54.487 26666-26732/mypkg D/AAudio: AAudioStream_requestStart(s#12) returned 0 ---------
2021-08-03 12:46:54.488 26666-26941/mypkg D/AudioStreamInternalPlay_Client: callbackLoop() entering >>>>>>>>>>>>>>>
2021-08-03 12:46:54.488 26666-26941/mypkg D/AudioStreamInternal_Client: onEventFromServer - got AAUDIO_SERVICE_EVENT_STARTED
2021-08-03 12:46:54.488 26666-26941/mypkg D/AAudioStream: setState(s#12) from 3 to 4

tristanjl · August 3, 2021, 10:39pm

Hi sviudes,

Thanks for that - I can see what looks to be the issue in the log. We will be adding a fix that will be included in the next release.

Tristan

sviudes · August 5, 2021, 3:36pm

That’s great news, thank you!

prollin · September 9, 2021, 6:52am

Just want to add that I am seeing the same issue (similar log) on the following devices:

Samsung Galaxy Tab S6 Lite
Samsung Galaxy S10+
(Android 11, wifi on or off, default fmod setup)

It happens randomly (usually within a few minutes of gameplay). So far the best workaround is to switch back to OpenSL as output.

tristanjl · September 13, 2021, 11:07pm

We’ve released 2.01.12/2.02.03 with a fix for this issue. It should now be solved by upgrading.

sviudes · September 15, 2021, 7:00am

Thank you!

OlexandrBodov · September 30, 2021, 1:38pm

Hi!
We suffered the same troubles. And that’s realy comforting to know that the issue is allready fixed.
But i could,nt find the stated 2.01.12/2.02.03 version.
https://prnt.sc/1u8719m
https://prnt.sc/1u87io4
Tha’s soudns lame… but please help me to find it )

tristanjl · October 1, 2021, 1:07am

We don’t have a unity verified version (one that is available on the unity store) just yet. If you select “All” instead of “Unity Verified”, you will be able to download the latest version.

OlexandrBodov · October 1, 2021, 9:06am

Thanks a lot! I have missed that option somehow…