dhewm3 icon indicating copy to clipboard operation
dhewm3 copied to clipboard

Game freezes after a toilet is flushed

Open JORGETECH opened this issue 1 year ago • 15 comments
trafficstars

As ridiculous as it sounds, I'm encountering an strange issue where every time a toilet is flushed in the game (for example, in the beginning of the game or in Alpha Labs Sector 2) the game freezes, the only way to exit from this situation is to kill the process.

I tried running gdb and it doesn't give me any errors or stack dumps (which makes sense in a way since the game doesn't crash, it just freezes), this is with version 1.5.2 from Github releases. I already verified the game files and the checksums coincide with version 1.3.1 of the game. My system is running Ubuntu 22.04.3 LTS with PipeWire audio system and amdgpu graphics drivers (running on top of a Ryzen 3400G).

If there is any way I can debug the issue better I would gladly help.

JORGETECH avatar Dec 26 '23 01:12 JORGETECH

When running it in gdb, can you (when it freezes) switch to the terminal running gdb and press Ctrl-C there? That should pause the execution so you can enter gdb commands to get a backtrace etc

DanielGibson avatar Dec 26 '23 01:12 DanielGibson

Thanks for the advice, after encountering the issue I pressed Ctrl-C and issued the bt command inside gdb and I got this backtrace:

#0  0x00000000004ecb30 in idFileSystemLocal::AddToReadCount(int) ()
#1  0x00000000004df0fe in idFile_InZip::Read(void*, int) ()
#2  0x0000000000411dd6 in idCinematicLocal::RoQInterrupt() ()
#3  0x0000000000412308 in idCinematicLocal::ImageForTime(int) ()
#4  0x0000000000431162 in idMaterial::UpdateCinematic(int) const ()
#5  0x00000000005dae45 in idWindow::Trigger() ()
#6  0x00007fffa6a7aa41 in idEntity::ActivateTargets(idEntity*) const () from /media/DATA1/Juegos/Doom 3/base.so
#7  0x00007fffa6b267f4 in idTrigger_Multi::TriggerAction(idEntity*) () from /media/DATA1/Juegos/Doom 3/base.so
#8  0x00007fffa6b6442f in idClass::ProcessEventArgPtr(idEventDef const*, long*) () from /media/DATA1/Juegos/Doom 3/base.so
#9  0x00007fffa6b693fa in idEvent::ServiceEvents() () from /media/DATA1/Juegos/Doom 3/base.so
#10 0x00007fffa6a9be92 in idGameLocal::RunFrame(usercmd_t const*) () from /media/DATA1/Juegos/Doom 3/base.so
#11 0x00000000004ff5eb in idSessionLocal::RunGameTic() ()
#12 0x00000000004ffef1 in idSessionLocal::Frame() ()
#13 0x00000000004b29ed in idCommonLocal::Frame() ()
#14 0x000000000040f43d in main ()

EDIT: This is from the encounter in Alpha Labs Sector 2 Lavatory, where a toilet flushes automatically, I suppose an enemy or event triggers it.

JORGETECH avatar Dec 26 '23 02:12 JORGETECH

Can you enter p readCount to show the current readCount value?

Also, what happens if you continue (continue in gdb) and then press ctrl-c again and get a new backtrace?

DanielGibson avatar Dec 26 '23 02:12 DanielGibson

Also, try building the current code from Github - maybe your issue is already fixed by pure chance, but more importantly, you'll get debug symbols and the backtrace in gdb will be more helpful (contain linenumbers; and the p readCount I suggested in the prior post will probably only work with debug symbols)

DanielGibson avatar Dec 26 '23 02:12 DanielGibson

Good idea, I'll build the current codebase and report back with the steps you mentioned

JORGETECH avatar Dec 26 '23 12:12 JORGETECH

Ok, so I built a Debug type binary in hopes of getting more useful backtraces. I did the same thing and got this backtrace with more information:

#0  0x00005555556f916f in unzReadCurrentFile (file=0x5555606a33e8, buf=0x555559201240, len=8)
    at /home/jorgetech/Temp/dhewm3/neo/framework/minizip/unzip.cpp:1721
#1  0x00005555556acda3 in idFile_InZip::Read (this=0x555563c8dfd0, buffer=0x555559201240, len=8)
    at /home/jorgetech/Temp/dhewm3/neo/framework/File.cpp:1263
#2  0x000055555557e423 in idCinematicLocal::RoQInterrupt (this=0x555563c0b070)
    at /home/jorgetech/Temp/dhewm3/neo/renderer/Cinematic.cpp:1430
#3  0x0000555555579d71 in idCinematicLocal::ImageForTime (this=0x555563c0b070, thisTime=63440)
    at /home/jorgetech/Temp/dhewm3/neo/renderer/Cinematic.cpp:426
#4  0x00005555555b5a21 in idMaterial::UpdateCinematic (this=0x555563be07f0, time=63456)
    at /home/jorgetech/Temp/dhewm3/neo/renderer/Material.cpp:2554
#5  0x00005555557e2295 in idWindow::StateChanged (this=0x5555663d6cd0, redraw=true)
    at /home/jorgetech/Temp/dhewm3/neo/ui/Window.cpp:545
#6  0x00005555557e20cb in idWindow::Trigger (this=0x5555663d6cd0) at /home/jorgetech/Temp/dhewm3/neo/ui/Window.cpp:515
#7  0x00005555557e20a1 in idWindow::Trigger (this=0x5555663d64b0) at /home/jorgetech/Temp/dhewm3/neo/ui/Window.cpp:513
#8  0x00005555557de0c8 in idUserInterfaceLocal::Trigger (this=0x5555663c5c20, _time=63456)
    at /home/jorgetech/Temp/dhewm3/neo/ui/UserInterface.cpp:520
#9  0x00007fffa67371eb in idEntity::ActivateTargets (this=0x55555e280f9c, activator=0x55555a8b5ed4)
    at /home/jorgetech/Temp/dhewm3/neo/game/Entity.cpp:3573
#10 0x00007fffa6805a5d in idTrigger_Multi::TriggerAction (this=0x55555e280f9c, activator=0x55555a8b5ed4)
    at /home/jorgetech/Temp/dhewm3/neo/game/Trigger.cpp:394
#11 0x00007fffa6805b5f in idTrigger_Multi::Event_TriggerAction (this=0x55555e280f9c, activator=0x55555a8b5ed4)
    at /home/jorgetech/Temp/dhewm3/neo/game/Trigger.cpp:413
#12 0x00007fffa684feab in idClass::ProcessEventArgPtr (this=0x55555e280f9c, ev=0x7fffa6f6b4a0 <EV_TriggerAction>, 
    data=0x7fffffffc980) at /home/jorgetech/Temp/dhewm3/neo/game/gamesys/Callbacks.cpp:38
#13 0x00007fffa68659db in idEvent::ServiceEvents () at /home/jorgetech/Temp/dhewm3/neo/game/gamesys/Event.cpp:529
#14 0x00007fffa6760128 in idGameLocal::RunFrame (this=0x7fffa6aa3240 <gameLocal>, clientCmds=0x7fffffffcae0)
    at /home/jorgetech/Temp/dhewm3/neo/game/Game_local.cpp:2370
#15 0x00005555556d4027 in idSessionLocal::RunGameTic (this=0x555555d971c0 <sessLocal>)
    at /home/jorgetech/Temp/dhewm3/neo/framework/Session.cpp:2890
#16 0x00005555556d3cb7 in idSessionLocal::Frame (this=0x555555d971c0 <sessLocal>)
    at /home/jorgetech/Temp/dhewm3/neo/framework/Session.cpp:2836
#17 0x0000555555679176 in idCommonLocal::Frame (this=0x555555d066e0 <commonLocal>)
    at /home/jorgetech/Temp/dhewm3/neo/framework/Common.cpp:2439
#18 0x00005555557fe7d8 in main (argc=1, argv=0x7fffffffdb68) at /home/jorgetech/Temp/dhewm3/neo/sys/linux/main.cpp:452

If I continue execution and do another backtrace I get almost the same output (this time without unzReadCurrentFile and idFile_InZip::Read ). The interesting thing is that when I continue the sound system seems to be still working but I guess Doom 3 engine runs the audio in a another thread.

Doing p readCount didn't work since the symbol wasn't present in that context but I continued again and did another backtrace where it did appear:

#0  0x00005555556bb110 in idFileSystemLocal::AddToReadCount (this=0x555555d946a0 <fileSystemLocal>, c=-102)
    at /home/jorgetech/Temp/dhewm3/neo/framework/FileSystem.cpp:371
#1  0x00005555556acdca in idFile_InZip::Read (this=0x555563c8dfd0, buffer=0x555559201240, len=8)
    at /home/jorgetech/Temp/dhewm3/neo/framework/File.cpp:1264
#2  0x000055555557e423 in idCinematicLocal::RoQInterrupt (this=0x555563c0b070)
    at /home/jorgetech/Temp/dhewm3/neo/renderer/Cinematic.cpp:1430
#3  0x0000555555579d71 in idCinematicLocal::ImageForTime (this=0x555563c0b070, thisTime=63440)
    at /home/jorgetech/Temp/dhewm3/neo/renderer/Cinematic.cpp:426
#4  0x00005555555b5a21 in idMaterial::UpdateCinematic (this=0x555563be07f0, time=63456)
    at /home/jorgetech/Temp/dhewm3/neo/renderer/Material.cpp:2554
#5  0x00005555557e2295 in idWindow::StateChanged (this=0x5555663d6cd0, redraw=true)
    at /home/jorgetech/Temp/dhewm3/neo/ui/Window.cpp:545
#6  0x00005555557e20cb in idWindow::Trigger (this=0x5555663d6cd0) at /home/jorgetech/Temp/dhewm3/neo/ui/Window.cpp:515
#7  0x00005555557e20a1 in idWindow::Trigger (this=0x5555663d64b0) at /home/jorgetech/Temp/dhewm3/neo/ui/Window.cpp:513
#8  0x00005555557de0c8 in idUserInterfaceLocal::Trigger (this=0x5555663c5c20, _time=63456)
    at /home/jorgetech/Temp/dhewm3/neo/ui/UserInterface.cpp:520
#9  0x00007fffa67371eb in idEntity::ActivateTargets (this=0x55555e280f9c, activator=0x55555a8b5ed4)
    at /home/jorgetech/Temp/dhewm3/neo/game/Entity.cpp:3573
#10 0x00007fffa6805a5d in idTrigger_Multi::TriggerAction (this=0x55555e280f9c, activator=0x55555a8b5ed4)
    at /home/jorgetech/Temp/dhewm3/neo/game/Trigger.cpp:394
#11 0x00007fffa6805b5f in idTrigger_Multi::Event_TriggerAction (this=0x55555e280f9c, activator=0x55555a8b5ed4)
    at /home/jorgetech/Temp/dhewm3/neo/game/Trigger.cpp:413
#12 0x00007fffa684feab in idClass::ProcessEventArgPtr (this=0x55555e280f9c, ev=0x7fffa6f6b4a0 <EV_TriggerAction>, 
    data=0x7fffffffc980) at /home/jorgetech/Temp/dhewm3/neo/game/gamesys/Callbacks.cpp:38
#13 0x00007fffa68659db in idEvent::ServiceEvents () at /home/jorgetech/Temp/dhewm3/neo/game/gamesys/Event.cpp:529
#14 0x00007fffa6760128 in idGameLocal::RunFrame (this=0x7fffa6aa3240 <gameLocal>, clientCmds=0x7fffffffcae0)
    at /home/jorgetech/Temp/dhewm3/neo/game/Game_local.cpp:2370
#15 0x00005555556d4027 in idSessionLocal::RunGameTic (this=0x555555d971c0 <sessLocal>)
    at /home/jorgetech/Temp/dhewm3/neo/framework/Session.cpp:2890
#16 0x00005555556d3cb7 in idSessionLocal::Frame (this=0x555555d971c0 <sessLocal>)
    at /home/jorgetech/Temp/dhewm3/neo/framework/Session.cpp:2836
#17 0x0000555555679176 in idCommonLocal::Frame (this=0x555555d066e0 <commonLocal>)
    at /home/jorgetech/Temp/dhewm3/neo/framework/Common.cpp:2439
#18 0x00005555557fe7d8 in main (argc=1, argv=0x7fffffffdb68) at /home/jorgetech/Temp/dhewm3/neo/sys/linux/main.cpp:452

The output of p readCount was as follows:

$1 = -1553467694

JORGETECH avatar Dec 26 '23 12:12 JORGETECH

Can you enter frame 1 in gdb (to go to the stack frame with idFile_InZip::Read() - if it's not in the line starting with #1, use another number accordingly), and then enter p fullPath.data to print the idFile_InZip::fullPath idStr that contains the pk4 file and the file within it?

DanielGibson avatar Dec 27 '23 03:12 DanielGibson

Can you show a screenshot of where the bug happens? I don't think the toilets at the beginning of the game are even flushable? Or do you have some mod installed that modifies them?

Can you attach $HOME/.local/share/dhewm3/dhewm3log.txt to a reply here?

DanielGibson avatar Dec 27 '23 04:12 DanielGibson

Can you show a screenshot of where the bug happens?

I'll attach an screenshot of the point where the game crashes, I made a savegame specifically for debugging in the first map of Alpha Labs Sector 2. There you kill some enemies before entering a "Security Checkpoint Junction" (here is where I made the savegame), then there is a Lavatory with some enemies, something similar to an earthquake (marsquake?) happens which makes some ceiling tiles fall (I believe this is unrelated to the freeze, just for context). Here the freeze happens when I get closer to the enemies in the lavatory and a I hear a toilet flush shortly after, it sometimes happens a bit later but it always triggers when I get closer.

Screenshot_20231228_012019

I don't think the toilets at the beginning of the game are even flushable?

Actually, I thought they were activated by using the fire button but I must be wrong, I reloaded a save from the Mars City level, the toilet flush sound there seems to be activated when I get close to one, then the freeze happens.

Or do you have some mod installed that modifies them?

I don't think so, when I open the Mods window in the menu only two elements appear, dhewm3 and d3xp, I suppose those correspond to the engine and the Resurrection of Evil expansion respectively.

Can you enter frame 1 in gdb (to go to the stack frame with idFile_InZip::Read() - if it's not in the line starting with #1, use another number accordingly), and then enter p fullPath.data to print the idFile_InZip::fullPath idStr that contains the pk4 file and the file within it?

I did all that, first of all, here is the output of frame 0 (it was #0 this time):

#0  0x00005555556acd94 in idFile_InZip::Read (this=0x555563bfb240, buffer=0x555559200260, len=-1793970722)
    at /home/jorgetech/Temp/dhewm3/neo/framework/File.cpp:1263
1263            int l = unzReadCurrentFile( z, buffer, len );

Then the output of p fullPath.data:

$1 = 0x555563b69c40 "/home/jorgetech/.local/share/dhewm3/base/pak003.pk4/sound/vo/video/mfs.roq"

I'll also attach the logfile you mentioned, actually I observed something interesting inside it. There are some warning which could be related:

dhewm3log.txt

WARNING: Opening OGG file 'sound/vo/video/mfs.ogg' with stb_vorbis
WARNING: Couldn't load sound 'sound/vo/video/mfs.wav' using default

After reading this I inspected the pk4 file that gdb mentioned, I found both the mfs.ogg and mfs.roq files in the correct path, but the strange thing is that it seems to be a completely unrelated audio from one of the videos you get in the PDA (the one about the Hydrocon device), nothing related to the Lavatory. So now I'm a bit confused. The even more strange thing is that I get similar backtrace pointing to the same file in the Mars City level, way before the Hydrocon device is even mentioned.

BTW, if you read the logs you will observe I have the game data duplicated in two different paths, I don't remember when I did this but the checksums are the same for all of them so I guess the engine prefers the ones from ".local/share/".

JORGETECH avatar Dec 28 '23 01:12 JORGETECH

Can you upload the savegame (in a .zip)? Maybe I can reproduce the issue with it..

DanielGibson avatar Dec 28 '23 06:12 DanielGibson

Also, make sure that the md5 sums of your pk4 files match the ones listed at https://dhewm3.org/#how-to-install and maybe try removing the duplicate game data

DanielGibson avatar Dec 28 '23 06:12 DanielGibson

Can you reproduce this freeze with pulseaudio instead of pipewire?
AFAIK pulseaudio is the default audio system in Ubuntu 22.04. What version of openal-soft is installed?

I'll try to reproduce this on my Fedora 39 system using pipewire 1.0 and openal-soft 23.1.

j4reporting avatar Dec 29 '23 00:12 j4reporting

I can't reproduce this on the first map and in AlphaLabs2 using the latest dhewm3 git master on a current fedora39 system. I loaded alphalabs2 with the map command and then 'give all' command.

OpenAL 1.19 does not have a pipewire backend, maybe try to switch to another available driver. At the very least, I would check that openal + pipewire is not the culprit here. Try to enable debugging for openal-soft and maybe pipewire too, and check if one of these systems lock up.

https://github.com/kcat/openal-soft/wiki/User%27s-Guide

j4reporting avatar Jan 01 '24 17:01 j4reporting

After reading this I inspected the pk4 file that gdb mentioned, I found both the mfs.ogg and mfs.roq files in the correct path, but the strange thing is that it seems to be a completely unrelated audio from one of the videos you get in the PDA (the one about the Hydrocon device), nothing related to the Lavatory.

That video however is played somewhere in alphalabs2 (not just the PDA), so it being there is not completely wrong. It's still possible that it's not the source of your freeze though.

I somehow doubt that it's because of pipewire, because audio is handled in a separate thread - even if something goes wrong there, the game should go on, I think (unless I'm missing something).

The savegame could really help.

DanielGibson avatar Jan 01 '24 20:01 DanielGibson

@JORGETECH could you provide the savegame, or has this issue magically resolved itself?

DanielGibson avatar Feb 03 '24 14:02 DanielGibson

Hi, sorry for not commenting in this issue for a long while. I took a break from playing the game after last Christmas and I completely forgot about this issue as a result.

I decided to investigate again and I came to the conclusion that it had something to do with my specific audio setup, I suspect it had something to do with PipeWire, after disabling the relevant services and enabling the Pulseaudio services the game no longer crashes!

The weird thing is that I decided to come back to PipeWire and test again and it doesn't crash with Pulseaudio running on top of PipeWire. The only conclusion I can have right now is that something was borked in my audio setup and messing around with the services somehow fixed it.

Since no one was able to reproduce the issue and I can no longer reproduce it I will close it. If anyone still wants the savegame to test it I can share it but I wouldn't loose any more time diagnosing it.

Anyways, thanks for the help.

JORGETECH avatar Mar 25 '24 16:03 JORGETECH