GRIM: Grim Fandango crash after solving the signpost in the Petrified Forest

[Die4Ever]

versioninfo=2.3.0pre233-gc62e0a307e

Language of the game: English
Version of the game: 2 CDs with gfupd101.exe

OS info:
Edition Windows 10 Home
Version 21H1
Installed on ‎11/‎3/‎2020
OS build 19043.1165
Experience Windows Feature Experience Pack 120.2212.3530.0

Bug Description:
I placed the signpost in the right spot, the door in the floor opened up, then I ran back to the previous screen to get in the car and the game just crashed.

Reproduction steps:
Just load the attached save file and walk to the right to cross to the next screen. Works with direct load.

[Die4Ever]

I was able to avoid the crash by moving the car to that screen before solving the sign puzzle, but I had to load an older save in order to do it.

[eriktorbjorn]

Valgrind log of the error happening:

==2424215== Thread 11 SDLTimer:
==2424215== Invalid read of size 8
==2424215==    at 0x1915C5D: Grim::Imuse::callback() (imuse.cpp:280)
==2424215==    by 0x1914DF7: Grim::Imuse::timerHandler(void*) (imuse.cpp:48)
==2424215==    by 0x3A39BE8: DefaultTimerManager::handler() (default-timer.cpp:111)
==2424215==    by 0x3A2F6F0: timer_handler(unsigned int, void*) (sdl-timer.cpp:37)
==2424215==    by 0x6DCCE31: ??? (in /usr/lib/x86_64-linux-gnu/libSDL2-2.0.so.0.16.0)
==2424215==    by 0x6DCC8B0: ??? (in /usr/lib/x86_64-linux-gnu/libSDL2-2.0.so.0.16.0)
==2424215==    by 0x6E5A138: ??? (in /usr/lib/x86_64-linux-gnu/libSDL2-2.0.so.0.16.0)
==2424215==    by 0x8477EAD: start_thread (pthread_create.c:463)
==2424215==    by 0x83A1A5E: clone (clone.S:95)
==2424215==  Address 0x259dbfd0 is 0 bytes inside a block of size 48 free'd
==2424215==    at 0x6CD769B: operator delete(void*) (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==2424215==    by 0x3DE3E0D: Audio::QueuingAudioStreamImpl::~QueuingAudioStreamImpl() (audiostream.cpp:368)
==2424215==    by 0x2A4BD6D: Common::DefaultDeleter<Audio::AudioStream>::operator()(Audio::AudioStream*) (ptr.h:383)
==2424215==    by 0x3DFAED0: Common::DisposablePtr<Audio::AudioStream, Common::DefaultDeleter<Audio::AudioStream> >::~DisposablePtr() (ptr.h:450)
==2424215==    by 0x3DFA61D: Audio::Channel::~Channel() (mixer.cpp:527)
==2424215==    by 0x3DF984C: Audio::MixerImpl::stopHandle(Audio::SoundHandle) (mixer.cpp:336)
==2424215==    by 0x1919A58: Grim::Imuse::startSound(char const*, int, int, int, int, int, Grim::Track*) (imuse_track.cpp:87)
==2424215==    by 0x19178FD: Grim::Imuse::startMusic(char const*, int, int, int) (imuse_script.cpp:85)
==2424215==    by 0x191734A: Grim::Imuse::playMusic(Grim::ImuseTable const*, int, bool) (imuse_music.cpp:142)
==2424215==    by 0x1916E39: Grim::Imuse::setMusicState(int) (imuse_music.cpp:50)
==2424215==    by 0x18F926E: Grim::SoundPlayer::setMusicState(int) (sound.cpp:80)
==2424215==    by 0x18BA99D: Grim::GrimEngine::mainLoop() (grim.cpp:1115)
==2424215==  Block was alloc'd at
==2424215==    at 0x6CD4F2F: operator new(unsigned long) (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==2424215==    by 0x3DE4098: Audio::makeQueuingAudioStream(int, bool) (audiostream.cpp:404)
==2424215==    by 0x19154A7: Grim::Imuse::restoreState(Grim::SaveGame*) (imuse.cpp:145)
==2424215==    by 0x18F930D: Grim::SoundPlayer::restoreState(Grim::SaveGame*) (sound.cpp:96)
==2424215==    by 0x18BAF73: Grim::GrimEngine::savegameRestore() (grim.cpp:1215)
==2424215==    by 0x18BA3A5: Grim::GrimEngine::mainLoop() (grim.cpp:978)
==2424215==    by 0x18B6CA4: Grim::GrimEngine::run() (grim.cpp:437)
==2424215==    by 0x918816: runGame(Plugin const*, Plugin const*, OSystem&, Common::String const&) (main.cpp:311)
==2424215==    by 0x91A0FF: scummvm_main (main.cpp:621)
==2424215==    by 0x915D26: main (posix-main.cpp:45)
==2424215==

So it's trying to access memory after it was freed.

[Die4Ever]

I myself have noticed that it's all too easy to do that with AudioStreams, I wonder if it's worth using smart pointers for them. I might take it upon myself to work on that

[eriktorbjorn]

I tried playing the game from the beginning, and it crashed in the exact same spot. Which I guess is good in a way...?

Edit: And it doesn't seem to happen until after you've solved the signpost puzzle. Just entering and leaving the room did not crash it for me.

[eriktorbjorn]

I've attached another savegame, right after arriving at the Petrified Forest. I figured that might make it easier to reproduce what happens right before the crash. (Of course, you still need to revive Glottis first but that's quicker than starting from the beginning.)

[eriktorbjorn]

I could avoid the crash by riding the Bone Wagon out of the room (which of course isn't an option in the first savegame), but then it crashed when I walked back to the room on foot.

[eriktorbjorn]

I suspect this bit of Imuse::startSound() is wrong:

	// If the track is fading out bring it back to the normal running tracks
	for (i = MAX_IMUSE_TRACKS; i < MAX_IMUSE_TRACKS + MAX_IMUSE_FADETRACKS; i++) {
		if (!scumm_stricmp(_track[i]->soundName, soundName) && !_track[i]->toBeRemoved) {

			Track *fadeTrack = _track[i];
			track = _track[i - MAX_IMUSE_TRACKS];

			if (track->used) {
				flushTrack(track);
				g_system->getMixer()->stopHandle(track->handle);
			}

			// Clone the settings of the given track
			memcpy(track, fadeTrack, sizeof(Track));
			track->trackId = i - MAX_IMUSE_TRACKS;
			// Reset the track
			fadeTrack->clear();
			// Mark as used for now so the track won't be reused again this frame
			track->used = true;

			return true;
		}
	}

Apparently the music that gets started when leaving the room is already playing on a fade out track (don't ask me why it's on fade out). So it "clones" the track back to an ordinary track, except when it stops the sound handle on the fade out track that deletes the underlying stream since it has the "dispose after use" flag.

I assume that disposing after use is generally a good thing, but not in this particular case?

Maybe it needs to do what Imuse::cloneToFadeOutTrack() does, where it apparently makes a new copy of the sound as well?

[antoniou79]

As far as I can tell, when moving tracks to fadeout (moveToFadeOutTrack()), the fadeout track maintains the same handle, whereas when cloning to fadeout, a new handle is created. Why not always use the clone to fadeout, which is safer?

Also for some reason the "used" field of the source position of the moved track remains true (same thing happens when cloning). The comment says "Mark as used for now so the track won't be reused again this frame", but it seems it keeps the used value longer than it should. It's possible that the "used" field has ambiguous usage here.

And, the clear() method, does not clear the handle field of the source track (there's a FIXME note about that), so in this case, trying to move the track back from fadeout to normal, the stopHandle is called on the (common) handle of the track, which is still in the "handle" field of the target position.

I guess that the "if clause" in startSound() is there for the case when the track in fadeout is a different one than the normal one is replacing? But there's no check for the (very likely) case that it is the same track with the same handle (if moveToFadeOutTrack() was used).

We could compare the sound handle we're stopping with the one that we need to keep working.
Ie. this works:

			if (track->used) {
				flushTrack(track);
				if (memcmp(&(track->handle), &(fadeTrack->handle), sizeof(Audio::SoundHandle)) != 0) {
					g_system->getMixer()->stopHandle(track->handle);
				}
			}

Not sure how we feel about memcmp on soundHandles, though.
And if we do this here, it probably would make sense to do this at least in moveToFadeOutTrack() (maybe in cloneToFadeOutTrack() for consistency) just in case we don't obliviously stop a handle that is supposed to keep playing.

[eriktorbjorn]

I don't really understand the whole fade out track thing. I tried adding some debug messages for the problematic 1071 - Signpost Room.IMC track.

What I can see is that whenever that piece of music starts (the first time being while you're talking to Glottis and he explains the situation), it will call both startSound() and cloneToFadeOutTrack() for it.

Whever the music changes, it will call moveToFadeOutTrack() for the it.

Where it crashes is the only time when it will call moveToFadeOutTrack(), immediately followed by startSound() for it.

But is that significant? I just don't know...

[eriktorbjorn]

It hits the table->opcode == 2 case in Imuse::playMusic(), so that's apparently where both the moveToFadeOuttrack() and startSound() calls come from. That's not unique to this particular case, but I guess it will crash if it's used to start music that's already playing.

[eriktorbjorn]

It goes from music state 1073 to music state 1071. Other than the id, these are identical in the grimStateMusictable:

	{2, 1071,   0, 3, 60, 127,   0, "1071 - Signpost Room.IMC"},
	{2, 1072,   0, 0, 60, 127,   0, "1072 - Navigation.IMC"},
	{2, 1073,   0, 3, 60, 127,   0, "1071 - Signpost Room.IMC"},

(There's yet another identical one with id 1079.)

That may have something to do with why it insists on starting the music again, even thought the "same" music is already playing.

[eriktorbjorn]

It was pointed out to me that moveToFadeOutTrack() is unique to the GrimE engine. The SCUMM version only uses cloneToFadeOutTrack().

The moveToFadeOutTrack() function was added in ​https://github.com/scummvm/scummvm/commit/6bb4658ea60548fca0a5304e7b21e603e8f2e107 to fix "the sound skipping a bit when a fade out starts because the clone track doesn't copy the queued buffers".

So I guess that answers antoniou79 question, "Why not always use the clone to fadeout, which is safer?"

And, as suspected, replacing moveToFadeOutTrack() with this:

Track *Imuse::moveToFadeOutTrack(Track *track, int fadeDelay) {
	Track *fadeTrack = cloneToFadeOutTrack(track, fadeDelay);
	flushTrack(track);
	return fadeTrack;
}

does seem to fix the crash. I couldn't say how much of the aforementioned skipping it reintroduces, though.

[eriktorbjorn]

The commit has been reverted in the release branch (not the trunk) so it should no longer crash there, at the possible cost of some skipping during crossfades. I haven't tried playing past this point myself, though.

[aquadran]

let's put change also to master for now to avoid crash, until properly resolved