FMOD stopping music after background / foreground iOS Application

FMOD Engine
1

I’m using FMOD for iOS 2.03.08. This same behavior was seen in FMOD for iOS 2.03.07

I have a game that plays background music on one channel and then other sound effects on different channels. Everything seems to work fine until I background / foreground the application. I hear the background music for less then a second after the call to mixerResume() and then I get a callback that the music has been stopped with a callstack:

#0	0x000000011dd500e8 in ::channelControlCallback(FMOD_CHANNELCONTROL *, FMOD_CHANNELCONTROL_TYPE, FMOD_CHANNELCONTROL_CALLBACK_TYPE, void *, void *) at SoundManager.cpp:67
#1	0x0000000121d857f4 in FMOD::ChannelControlI::executeCallback ()
#2	0x0000000121cc7b68 in FMOD::ChannelI::stopEx ()
#3	0x0000000121c9f438 in FMOD::SystemI::updateChannels ()
#4	0x0000000121c9ee14 in FMOD::SystemI::updateInternal ()
#5	0x0000000121d438fc in FMOD::System::update ()

The log reports the very suspicious FMOD_RESULT = 19 -- Unsupported file or audio format. but the audio format (mp3) was supported and playing prior to the background / resume. If I force the music to stop and play again the same exact file, it works fine.

[LOG] FMOD_System_Create                       : Header version = 2.03.08. Current version = 2.03.08.
[LOG] SystemI::setOutputInternal               : Setting output to 'FMOD Core Audio Output'
[LOG] Thread::initThread                       : Init FMOD stream thread. Affinity: 0x4000000000000003, Priority: 0xFFFF7FFB, Stack Size: 98304, Semaphore: No, Sleep Time: 10, Looping: Yes.
[LOG] Thread::initThread                       : Init FMOD mixer thread. Affinity: 0x4000000000000001, Priority: 0xFFFF7FFA, Stack Size: 81920, Semaphore: Yes, Sleep Time: 0, Looping: Yes.
TID 305594207 : 2800410841 ms    +0 : [LOG] SystemI::createSound                     : FMOD_NONBLOCKING specified.  Putting into queue to be opened asynchronously!
TID 305594207 : 2800410841 ms    +0 : [LOG] Thread::initThread                       : Init FMOD nonblocking thread (0). Affinity: 0x4000000000000003, Priority: 0xFFFF7FFC, Stack Size: 114688, Semaphore: Yes, Sleep Time: 0, Looping: Yes.
TID 305595111 : 2800410881 ms   +38 : [LOG] Thread::initThread                       :     Init FMOD file thread. Affinity: 0x4000000000000003, Priority: 0xFFFF7FFC, Stack Size: 65536, Semaphore: No, Sleep Time: 10, Looping: Yes.
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/platforms/ios/src/fmod_codec_audioqueue.cpp(151) : TID 305594207 : 2800412031 ms    +0 : [LOG] FMOD_RESULT = 19 -- Unsupported file or audio format.
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_codec_fsb5.cpp(615) : TID 305594207 : 2800412031 ms    +0 : [LOG] FMOD_RESULT = 19 -- Unsupported file or audio format.
TID 305595011 : 2800415274 ms    +3 : [LOG] Thread::callback                         : FMOD mixer thread finished.
TID 305594207 : 2800417840 ms    +0 : [LOG] Thread::initThread                       : Init FMOD mixer thread. Affinity: 0x4000000000000001, Priority: 0xFFFF7FFA, Stack Size: 81920, Semaphore: Yes, Sleep Time: 0, Looping: Yes.
TID 305595417 : 2800431573 ms    +6 : [LOG] Thread::callback                         : FMOD mixer thread finished.
TID 305594207 : 2800433257 ms    +0 : [LOG] Thread::initThread                       : Init FMOD mixer thread. Affinity: 0x4000000000000001, Priority: 0xFFFF7FFA, Stack Size: 81920, Semaphore: Yes, Sleep Time: 0, Looping: Yes.

This seems to only impact our iOS build and has not been found by QA on Android or Kindle.

I’ve turned on as much debug info as I know how in FMOD, but I’m not really sure what else to look at to debug this issue. Any help is much appreciated.

Thanks,
Steven Behnke

2

Hey Steven,

The logs you’ve shared appear to indicate an issue when FMOD tries to open and read the header of the source audio file, but unfortunately I haven’t been able to reproduce the issue on my end. A few questions:

  • Are any FMOD API calls made between calling mixerSuspend and mixerResume?
  • Besides suspending/resuming the mixer, are you doing anything to manage the AudioSession that occurs when the application is backgrounded/foregrounded, or receives an interruption from the OS?
  • How is the audio being loaded by FMOD (i.e. sample, stream, compressed sample)? When FMOD’s debug level is set to Log, all relevant details about the loading and creation of sounds is logged - could I get you to share the logs for the relevant audio file?
3

I have just double checked that I don’t do anything between mixerSuspend() and mixerResume(). When the App enters the background we also pause our render loop so the update() call is also suppressed. This is not 100% reproducible with every background / foreground event so I had to attempt it a couple of times with more logging on to get it to reproduce. I have omitted many of the File::checkBufferedStatus and File::read calls from the log between the suspend / resume events because I don’t think it is relevant.

The way the audio is being loaded goes like this:

        FMOD_CREATESOUNDEXINFO exinfo;
        
        memset(&exinfo, 0, sizeof(FMOD_CREATESOUNDEXINFO));
        exinfo.cbsize = sizeof(FMOD_CREATESOUNDEXINFO);
        exinfo.nonblockcallback = nonblockcallback;

        FMOD_RESULT result = m_fmodSystem->createStream(fullPath.c_str(),  FMOD_LOOP_NORMAL | FMOD_2D | FMOD_NONBLOCKING, &exinfo, &m_music);

...

// Call back for non-blocking IO.
void SoundManager::nonBlockingPlayMusic() {
...
    FMOD_RESULT result;
    int numSubSounds = 0;
    result = m_music->getNumSubSounds(&numSubSounds);
    
    FMOD_CHECK_RESULT(result);

    if (numSubSounds)
    {
        FMOD_CHECK_RESULT(m_music->getSubSound(0, &m_music));
    }

result = m_fmodSystem->playSound(m_music, m_musicGroup, true, &m_musicChannel);
    if(result == FMOD_OK)
    {
        m_musicChannel->setCallback(channelControlCallback); // Only for detecting this error
        FMOD_CHECK_RESULT(m_musicChannel->setPaused(false));
    }
    else
    {
        FMOD_CHECK_RESULT(result);
    }
...
}

Initialization logs:

[LOG] FMOD_System_Create                       : Header version = 2.03.08. Current version = 2.03.08.
[LOG] SystemI::setOutputInternal               : Setting output to 'FMOD Core Audio Output'
[LOG] Thread::initThread                       : Init FMOD stream thread. Affinity: 0x4000000000000003, Priority: 0xFFFF7FFB, Stack Size: 98304, Semaphore: No, Sleep Time: 10, Looping: Yes.
[LOG] Thread::initThread                       : Init FMOD mixer thread. Affinity: 0x4000000000000001, Priority: 0xFFFF7FFA, Stack Size: 81920, Semaphore: Yes, Sleep Time: 0, Looping: Yes.
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(746) : TID 312324224 : 2892930435 ms    +0 : [LOG] MemPool::alloc                           :    600 bytes (0x10417d058) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi_channel.cpp(116) #166
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(746) : TID 312324224 : 2892930435 ms    +0 : [LOG] MemPool::alloc                           :    720 bytes (0x10417d958) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_pluginfactory.cpp(1458) #167
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(746) : TID 312324224 : 2892930435 ms    +0 : [LOG] MemPool::alloc                           :     21 bytes (0x600000400ea8) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_string.cpp(362) #168
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(746) : TID 312324224 : 2892930435 ms    +0 : [LOG] MemPool::alloc                           :    600 bytes (0x10417dc28) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi_channel.cpp(116) #169
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(746) : TID 312324224 : 2892930435 ms    +0 : [LOG] MemPool::alloc                           :    720 bytes (0x10417de88) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_pluginfactory.cpp(1458) #170
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(746) : TID 312324224 : 2892930435 ms    +0 : [LOG] MemPool::alloc                           :     14 bytes (0x60000004c668) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_string.cpp(362) #171
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi.cpp(4084) : TID 312324224 : 2892932125 ms +1690 : [LOG] SystemI::createSound                     : filename = /Users/sbehnke/Library/Developer/CoreSimulator/Devices/7A8C769E-35BF-48C0-9CA0-6D3E48CE8AA6/data/Containers/Bundle/Application/4C163728-C306-46AF-BB8B-D3B12355D3E7/Wizard-of-Oz.app/worlds/rainbow_world/sounds/Lobby_Music.mp3 : mode 0001008a
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi.cpp(4088) : TID 312324224 : 2892932125 ms    +0 : [LOG] SystemI::createSound                     : FMOD_NONBLOCKING specified.  Putting into queue to be opened asynchronously!
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(746) : TID 312324224 : 2892932125 ms    +0 : [LOG] MemPool::alloc                           :    392 bytes (0x171428778) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi.cpp(4094) #172
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(746) : TID 312324224 : 2892932125 ms    +0 : [LOG] MemPool::alloc                           :    328 bytes (0x171428908) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi.cpp(4142) #173
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(746) : TID 312324224 : 2892932125 ms    +0 : [LOG] MemPool::alloc                           :    233 bytes (0x600003d82fd8) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi.cpp(4156) #174
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_async.cpp(384) : TID 312324224 : 2892932125 ms    +0 : [LOG] AsyncThread::getAsyncThread              : index = 0 / 5
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(746) : TID 312324224 : 2892932125 ms    +0 : [LOG] MemPool::alloc                           :    384 bytes (0x171428a58) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_async.cpp(401) #175
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(746) : TID 312324224 : 2892932125 ms    +0 : [LOG] MemPool::alloc                           :     72 bytes (0x6000062857c8) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/platforms/ios/src/fmod_os_misc.cpp(509) #176
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_thread.cpp(216) : TID 312324224 : 2892932126 ms    +1 : [LOG] Thread::initThread                       : Init FMOD nonblocking thread (0). Affinity: 0x4000000000000003, Priority: 0xFFFF7FFC, Stack Size: 114688, Semaphore: Yes, Sleep Time: 0, Looping: Yes.
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(746) : TID 312324224 : 2892932126 ms    +0 : [LOG] MemPool::alloc                           :    280 bytes (0x1714283b8) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/platforms/ios/src/fmod_os_misc.cpp(440) #177
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(848) : TID 312335365 : 2892932126 ms    +0 : [LOG] MemPool::free                            :    280 bytes (0x1714283b8) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/platforms/ios/src/fmod_os_misc.cpp(373)
../../src/fmod_async.h(74)                                   : TID 312324224 : 2892932127 ms    +1 : [LOG] AsyncThread::add                         : add sound to async queue : soundi = 0x171428778, queue head = 0x171428ba8, queue count = 0
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_async.cpp(193) : TID 312335365 : 2892932127 ms    +0 : [LOG] AsyncThread::threadFunc                  : Starting Asynchronous operation on sound 0x171428778
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi_sound.cpp(621) : TID 312335365 : 2892932127 ms    +0 : [LOG] SystemI::createSoundInternal             :     Create name='<REDACTED>/Music.mp3', mode=0x0001008A
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi_sound.cpp(627) : TID 312335365 : 2892932127 ms    +0 : [LOG] SystemI::createSoundInternal             :     exinfo->cbsize             = 224
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi_sound.cpp(679) : TID 312335365 : 2892932128 ms    +1 : [LOG] SystemI::createSoundInternal             :     exinfo->nonblockcallback   = 0x11b6e1958
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(746) : TID 312335365 : 2892932128 ms    +0 : [LOG] MemPool::alloc                           :        512 bytes (0x171428d68) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi_sound.cpp(569) #178
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(409) : TID 312335365 : 2892932128 ms    +0 : [LOG] File::open                               :     name /Users/sbehnke/Library/Developer/CoreSimulator/Devices/7A8C769E-35BF-48C0-9CA0-6D3E48CE8AA6/data/Containers/Bundle/Application/4C163728-C306-46AF-BB8B-D3B12355D3E7/Wizard-of-Oz.app/worlds/rainbow_world/sounds/Lobby_Music.mp3 : length 0
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(482) : TID 312335365 : 2892932129 ms    +1 : [LOG] File::open                               :     done.  handle 0x171428d68.  File size = 216711
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi_sound.cpp(906) : TID 312335365 : 2892932129 ms    +0 : [LOG] SystemI::createSoundInternal             :     16 codecs found.  Scan all until one succeeds
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi_sound.cpp(965) : TID 312335365 : 2892932129 ms    +0 : [LOG] SystemI::createSoundInternal             :     Scan for tags.
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(1626) : TID 312335365 : 2892932129 ms    +0 : [LOG] File::seek                               :     0x171428d68 seek 0 bytes to 0
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_codec_tag.cpp(106) : TID 312335365 : 2892932129 ms    +0 : [LOG] CodecTag::openInternal                   :     attempting to open ID3 or ASF tags..
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(1626) : TID 312335365 : 2892932129 ms    +0 : [LOG] File::seek                               :     0x171428d68 seek 216583 bytes to 216583
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(1024) : TID 312335365 : 2892932129 ms    +0 : [LOG] File::read                               :     0x171428d68----> want to read 3
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(863) : TID 312335365 : 2892932129 ms    +0 : [LOG] File::checkBufferedStatus                :     0x171428d68    mCurrentPosition 216583 mNextPosition 0 nextpos diffbytes -216583 diff -1
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(796) : TID 312335365 : 2892932129 ms    +0 : [LOG] File::seekAndReset                       :     0x171428d68    seek to 215040
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(797) : TID 312335365 : 2892932131 ms    +2 : [LOG] File::seekAndReset                       :     0x171428d68    reset mBufferPos to 1543
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(924) : TID 312335365 : 2892932131 ms    +0 : [LOG] File::checkBufferedStatus                :     0x171428d68    FORCIBLY FILL FRONTBUFFER
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(620) : TID 312335365 : 2892932131 ms    +0 : [LOG] File::flip                               :     0x171428d68    **** fill   to 0 with 2048 bytes.  mBlockOffset 0 mBufferSkip 0 mAsyncRead 0
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(726) : TID 312335365 : 2892932131 ms    +0 : [LOG] File::flip                               :     0x171428d68    **** filled to        0 got      1671 bytes
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(1122) : TID 312335365 : 2892932131 ms    +0 : [LOG] File::read                               :     0x171428d68    copied 3 bytes from mBufferPos = 1543
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(1137) : TID 312335365 : 2892932132 ms    +1 : [LOG] File::read                               :     0x171428d68<---- done
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(1024) : TID 312335365 : 2892932132 ms    +0 : [LOG] File::read                               :     0x171428d68----> want to read 30
...

The new log shows more interesting data on the resume condition where the background audio stops:

/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(863) : TID 312335201 : 2892966964 ms    +0 : [LOG] File::checkBufferedStatus                : 0x171428d68    mCurrentPosition 156045 mNextPosition 180224 nextpos diffbytes 24179 diff 2
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(1122) : TID 312335201 : 2892966964 ms    +0 : [LOG] File::read                               : 0x171428d68    copied 261 bytes from mBufferPos = 24973
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(1137) : TID 312335201 : 2892966964 ms    +0 : [LOG] File::read                               : 0x171428d68<---- done
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(1626) : TID 312335201 : 2892966987 ms   +23 : [LOG] File::seek                               : 0x171428d68 seek 0 bytes to 156306
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(1024) : TID 312335201 : 2892966987 ms    +0 : [LOG] File::read                               : 0x171428d68----> want to read 208
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(863) : TID 312335201 : 2892966987 ms    +0 : [LOG] File::checkBufferedStatus                : 0x171428d68    mCurrentPosition 156306 mNextPosition 180224 nextpos diffbytes 23918 diff 2
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(1122) : TID 312335201 : 2892966987 ms    +0 : [LOG] File::read                               : 0x171428d68    copied 208 bytes from mBufferPos = 25234
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(1137) : TID 312335201 : 2892966987 ms    +0 : [LOG] File::read                               : 0x171428d68<---- done
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi.cpp(3717) : TID 312324224 : 2892967008 ms   +21 : [LOG] SystemI::mixerSuspend                    : Suspending output.
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(746) : TID 312324224 : 2892967010 ms    +2 : [LOG] MemPool::alloc                           :      8 bytes (0x600000029a38) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi_driver.cpp(281) #278
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_thread.cpp(172) : TID 312336377 : 2892967023 ms   +13 : [LOG] Thread::callback                         : FMOD mixer thread finished.
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(848) : TID 312324224 : 2892967025 ms    +2 : [LOG] MemPool::free                            :  16392 bytes (0x1069cca08) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_output.cpp(1848)
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(848) : TID 312324224 : 2892967025 ms    +0 : [LOG] MemPool::free                            :   4184 bytes (0x1069e4208) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_dsp_resampler.cpp(209)
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(848) : TID 312324224 : 2892967025 ms    +0 : [LOG] MemPool::free                            :    736 bytes (0x1044aee88) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi_driver.cpp(313)
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi.cpp(3769) : TID 312324224 : 2892968448 ms +1423 : [LOG] SystemI::mixerResume                     : Resuming output.
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/platforms/ios/src/fmod_codec_audioqueue.cpp(236) : TID 312335201 : 2892968448 ms    +0 : [ERR] CodecAudioQueue::readInternal            : Cannot offline render audio queue. (err: -50)
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/platforms/ios/src/fmod_output_coreaudio.mm(152) : TID 312324224 : 2892968448 ms    +0 : [LOG] OutputCoreAudio::init                    : Hardware buffer size: 480 samples, hardware sample rate: 48000Hz, hardware channels: 2
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(746) : TID 312324224 : 2892968449 ms    +1 : [LOG] MemPool::alloc                           :  16392 bytes (0x106369a08) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_output.cpp(1828) #279
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/platforms/ios/src/fmod_output_coreaudio.mm(213) : TID 312324224 : 2892968449 ms    +0 : [LOG] OutputCoreAudio::init                    : Maximum hardware read size: 4096 samples, Software buffer size: 512 samples, Number of software buffers: 4.
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/platforms/ios/src/fmod_output_coreaudio.mm(216) : TID 312324224 : 2892968449 ms    +0 : [WRN] OutputCoreAudio::init                    : DSP buffer size * DSP num buffers is potentially too small.
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi_driver.cpp(415) : TID 312324224 : 2892968449 ms    +0 : [LOG] SystemI::startDriver                     : Output requires a sample rate of 48000Hz, resampling will occur.
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(746) : TID 312324224 : 2892968449 ms    +0 : [LOG] MemPool::alloc                           :    736 bytes (0x1042c5108) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi_driver.cpp(487) #280
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(746) : TID 312324224 : 2892968449 ms    +0 : [LOG] MemPool::alloc                           :   4184 bytes (0x106363a08) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_dsp_resampler.cpp(169) #281
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_thread.cpp(216) : TID 312324224 : 2892968449 ms    +0 : [LOG] Thread::initThread                       : Init FMOD mixer thread. Affinity: 0x4000000000000001, Priority: 0xFFFF7FFA, Stack Size: 81920, Semaphore: Yes, Sleep Time: 0, Looping: Yes.
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(746) : TID 312324224 : 2892968449 ms    +0 : [LOG] MemPool::alloc                           :    280 bytes (0x1042db6e8) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/platforms/ios/src/fmod_os_misc.cpp(440) #282
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(848) : TID 312336511 : 2892968450 ms    +1 : [LOG] MemPool::free                            :    280 bytes (0x1042db6e8) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/platforms/ios/src/fmod_os_misc.cpp(373)
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_memory.cpp(848) : TID 312324224 : 2892968451 ms    +1 : [LOG] MemPool::free                            :      8 bytes (0x600000029a38) /opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_systemi_driver.cpp(452)
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(1626) : TID 312324224 : 2892968456 ms    +5 : [LOG] File::seek                               : 0x171428d68 seek -469 bytes to 156045
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(1024) : TID 312324224 : 2892968456 ms    +0 : [LOG] File::read                               : 0x171428d68----> want to read 261
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(863) : TID 312324224 : 2892968456 ms    +0 : [LOG] File::checkBufferedStatus                : 0x171428d68    mCurrentPosition 156045 mNextPosition 180224 nextpos diffbytes 24179 diff 2
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(1122) : TID 312324224 : 2892968456 ms    +0 : [LOG] File::read                               : 0x171428d68    copied 261 bytes from mBufferPos = 24973
/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/src/fmod_file.cpp(1137) : TID 312324224 : 2892968456 ms    +0 : [LOG] File::read                               : 0x171428d68<---- done

The log is too big to include here and as a new user I cannot upload it. I will email it to support@fmod.com if you need more than what I’ve provided.

Thanks,
Steven

4

Thanks for the additional logs.

After some more testing, it seems like this issue is related to the buffer size that FMOD is attempting to request from the AudioQueue codec that is decoding the file. The only way I’ve been able to (similarly sporadically) reproduce this is by making FMOD’s DSP buffer size too small for the AVAudioSession, and interrupt the FMOD application with another application which modifies the AVAudioSession in some way (i.e. the buffer size) such that FMOD isn’t able to recover.

I’d recommend increasing the FMOD system’s DSP buffer size, and also playing the sound as a sample or compressed sample instead of a stream, and seeing whether that makes any difference.

If that doesn’t work, I have a few extra questions for you:

  • Is your file being loaded as an mp3, or from an fsb file? Your code snippet is opening an fsb, but the sound creation in the log is opening an mp3. What format is the mp3 encoded as in the fsb?
  • What setup, if any, are you doing for your application’s AVAudioSession, including the sample rate, preferred IO buffer duration, etc.? Are you using the code provided with FMOD’s iOS examples, or your own?
  • Are any other applications playing audio during the time you suspend and resume your application and get the error?

As for sharing larger files, you’re welcome to use the uploads tab of your FMOD user profile, though our support email also works.

5

I tried doubling the DSP buffer size and that seemed to help some, but after 3 attempts the music would still die. I uploaded the log from that session to the user profile tab. The error with the music occurred when I see this in the log file:

/opt/teamcity-agent/work/c1c3f17eb167c494/core_api/platforms/ios/src/fmod_codec_audioqueue.cpp(236) : TID 315705276 : 2923037519 ms    +4 : [ERR] CodecAudioQueue::readInternal            : Cannot offline render audio queue. (err: -50)

The other two times this was missing and things worked as expected.

I didn’t realize the code we were using was trying to use a .fsb file. We don’t use them only .mp3 files so I removed the subSound calls. That also had no impact on hearing the sound.

What ultimately resolved this issue for me was to use createSound instead of createStream. Once I did this, it was able to play / resume without issue many times. Hope this helps. I wonder if it is something to do with the amount of buffer that is filled when backgrounding the app, or something like this. Currently it appears that using the non-blocking compressed sample will work for our purposes. I’m cleaning up the code and sending it off to QA.

Hope this helps find the ultimate issue with streaming.

Thanks,
Steven Behnke