Assertion when starting a new Classic Doom game

[DanielGibson]

Assertion in idSampleDecoderLocal::DecodeOGG():

if ( sample->nonCacheData == NULL ) {
	assert( false );	// this should never happen
	...

backtrace

AssertFailed() at .../neo/idlib/Lib.cpp:521 0x5555558ac04a	
idSampleDecoderLocal::DecodeOGG() at .../neo/sound/snd_decoder.cpp:536 0x555555789283	
idSampleDecoderLocal::Decode() at .../neo/sound/snd_decoder.cpp:462 0x555555788f85	
idSoundChannel::GatherChannelSamples() at .../neo/sound/snd_emitter.cpp:295 0x55555578cdae	
idSoundWorldLocal::AddChannelContribution() at .../neo/sound/snd_world.cpp:1,918 0x55555579f543	
idSoundWorldLocal::MixLoop() at .../neo/sound/snd_world.cpp:602 0x55555579a284	
idSoundSystemLocal::AsyncUpdateWrite() at .../neo/sound/snd_system.cpp:817 0x555555794161	
idCommonLocal::SingleAsyncTic() at .../neo/framework/Common.cpp:2,533 0x5555556740ba	
idCommonLocal::Async() at .../neo/framework/Common.cpp:2,586 0x55555567420c	
AsyncTimer() at .../neo/framework/Common.cpp:2,777 0x555555674a3e	
...

Reproduction: ./dhewm3 +set fs_basepath ../../doom3data/ +set fs_game cdoom -> New Game -> Hurt Me Plenty (or whatever)

The soundsample is sound/music/cdoomtheme.ogg (the menu music), it has previously been purged via
idSessionLocal::ExecuteMapChange() -> idSoundSystemLocal::EndLevelLoad() -> idSoundCache::EndLevelLoad()

This bug didn't happen (or at least I can't reproduce it, maybe it happens less often) in 1.5.0 or when setting com_asyncSound 2 which reduces the sound update frequency (how often MixLoop() is called) to 10 times per second instead of 60 times per second.
So it might be some kind of race condition?

I'll continue investigating, currently this is holding up releasing 1.5.2 RC2

[DanielGibson]

This does not (or in fact, very rarely) happen with com_asyncSound 2 (=> sounds only updated every ~100ms) because then usually no idSoundWorldLocal::MixLoop() is called between purging that sound and (the last) switching to the game soundworld (aka idSession::sw; that sample is only used in the idSessionLocal::menuSoundWorld).

This is with com_asyncSound 2 (those numbers in the 23XXX range are from Sys_Milliseconds(), i.e. milliseconds since game has started => they allow calculating the time elapsed between multiple logged events):

----- idSoundCache::EndLevelLoad -----
 !!! 23615: purging sound sample 0x55d12e37a460 with name sound/music/cdoomtheme.ogg !!! 
(...)
12 warnings
XX 23621: setting currentSoundWorld from menuSoundWorld to sw
XX 23621: setting currentSoundWorld from sw to NULL
XX 23633: setting currentSoundWorld from NULL to sw
XX 23634: setting currentSoundWorld from sw to menuSoundWorld
XX 23654: Heartbeat_f() : server is not running
XX 23654: setting currentSoundWorld from menuSoundWorld to sw
!!! MixLoop() 23691 com_ticNumber 1420 
!!! MixLoop() 23787 com_ticNumber 1426 
!!! MixLoop() 23883 com_ticNumber 1432

As you can see, the first time idSoundWorldLocal::MixLoop() is called after purging cdoomtheme.ogg is 76ms later - and 37ms after idSoundSystemLocal::currentSoundWorld is set to sw (the game sound world) for the last time (soon after that the level is actually loaded and shown).

The same with com_asyncSound 1 (here the milliseconds are in the 15XXX range):

----- idSoundCache::EndLevelLoad -----
 !!! 15499 purging sound sample 0x55a7bb44b710 with name sound/music/cdoomtheme.ogg
(...)
12 warnings
XX 15505: setting currentSoundWorld from menuSoundWorld to sw
XX 15505: setting currentSoundWorld from sw to NULL
XX 15516: setting currentSoundWorld from NULL to sw
XX 15517: setting currentSoundWorld from sw to menuSoundWorld
!!! MixLoop() 15531 com_ticNumber 908 
// the following are the assertion this is about, replaced with a printf():
 15531  XXXXXXXX would have asserted - sample: sound/music/cdoomtheme.ogg !!!!!!
 15531  XXXXXXXX would have asserted - sample: sound/music/cdoomtheme.ogg !!!!!!
 15531  XXXXXXXX would have asserted - sample: sound/music/cdoomtheme.ogg !!!!!!
XX 15539 Heartbeat_f() : server is not running
XX 15539: setting currentSoundWorld from menuSoundWorld to sw
!!! MixLoop() 15547 com_ticNumber 909 
!!! MixLoop() 15563 com_ticNumber 910 
!!! MixLoop() 15579 com_ticNumber 911 

So MixLoop() is called at 15531 milliseconds, 32 milliseconds after the sample sound/music/cdoomtheme.ogg has been purged, and 8 milliseconds before idSoundSystemLocal::currentSoundWorld is set to sw (the game sound world) for the last time.

BTW, if I open the menu after that (by pressing Escape), no error happens and the music starts playing again. Probably it's reloaded when the menu is properly opened?

So now I know why it's a lot more likely to happen since 1.5.1 (in 1.5.0 the sound updates always were every 100ms).
I'm still not sure what to do about this, though..