Touhou Luna Nights Issues

[firebingo]

Hello, I am having issues attempting to TAS Touhou Luna Nights via wine on Debian 10 that I believe are threading and audio related.

To get the game to launch as I believe is expected with a game maker game I have to turn Time tracking>clock_gettime() on. Without any other settings the game will freeze after the splash logos before the main menu. This seems to be "fixable" in a few ways that also cause other problems.

The first thing I tried to fix this was turning Keep main first thread on. This for the most part seemed to be stable and allows save states and movie recording/playback to work. However around frame 4000-5000 into the game libTAS starts logging Audio mixing will underrun, waiting for the game to send audio samples every frame and Timeout every few frames or so. This goes on for about 1500-2000 frames before wine crashes. Changing the audio sample rate to something other than 44khz causes wine to crash I believe as soon as the audio samples problem starts.

Turning Keep main first thread off and setting clock_gettime() for Time tracking all threads also appears to fix the audio crash but causes the game to run much slower and makes it prone to crash around save states.

Turning uncontrolled time on also appears to fix the crashing issue and allows save states to work. But I am assuming this will eventually cause determinism problems and allows the game to save even with prevent writing to disk on.

Changing wine to use pulseaudio instead of alsa with keep main first thread on seems to allow the game to run as expected besides the audio not being properly controlled. I have not tested far enough to see if this will cause determinism issues later on.

I also have set Wait timeout to No waits otherwise save states are unstable. But otherwise the game runs with Native waits on. And I have tested these various other debug options with both.

Also regardless of most of these settings the starting settings menu and splash logos usually are also logging Audio mixing will underrun, waiting for the game to send audio samples every frame until you get to the main menu.

I have tested this with the latest 1.3.5 .deb release and building from commit 062c76b I have not been able to test with the latest f875e94 as that fails to launch wine after logging "Building our trampoline function"

Here is an example of a backtrace that gets logged when the game crashes with Keep main first thread on:

Unhandled exception: page fault on read access to 0x0000000c in 32-bit code (0xf7eea4e2).
Register dump:
 CS:0023 SS:002b DS:002b ES:002b FS:0063 GS:006b
 EIP:f7eea4e2 ESP:06b0f1a0 EBP:7c5e93dc EFLAGS:00210246(  R- --  I  Z- -P- )
 EAX:00000000 EBX:f7fc4918 ECX:e661b2b8 EDX:00000000
 ESI:00000000 EDI:00fe502a
Stack dump:
0x06b0f1a0:  00000001 f7be16ad e661b260 0000000b
0x06b0f1b0:  f7fc4918 000003ba 06b0f398 f7fe205d
0x06b0f1c0:  00000000 00000000 f7fc4918 f7ec48b3
0x06b0f1d0:  f7fc4918 00000000 f7eea46b f7fc4918
0x06b0f1e0:  f7fc4918 000003ba 06b0f398 f7ee33c8
0x06b0f1f0:  7c5e93dc 00000000 00fe502a f7ee2eb6
Backtrace:
=>0 0xf7eea4e2 SDL_Init+0x399b2() in libtas.so (0x7c5e93dc)
  1 0xf7ee33c8 SDL_Init+0x32897() in libtas.so (0x06b0f398)
  2 0xf7e75a42 SDL_Init+0xffffffff() in libtas.so (0xf7fc6300)
  3 0xf7e79b54 SDL_Init+0xffffffff() in libtas.so (0x06b0fd38)
  4 0xf7e83603 SDL_Init+0xffffffff() in libtas.so (0x06b0fd98)
  5 0x7dcbbffa X11DRV_ClipCursor+0x6c69() in winex11 (0x06b0fdf8)
  6 0x7df933a7 wined3d_swapchain_create+0x786() in wined3d (0x06b0fec8)
  7 0x7df2535c wined3d_buffer_create+0x10cbb() in wined3d (0x06b0fef8)
  8 0x7df26656 wined3d_buffer_create+0x11fb5() in wined3d (0x06b0ff48)
  9 0x7bccfc80 call_thread_func_wrapper+0xb() in ntdll (0x06b0ff5c)
  10 0x7bcd3767 RtlCaptureStackBackTrace+0x1d6() in ntdll (0x06b0ffdc)
  11 0x7bccfc72 call_thread_exit_func+0x31() in ntdll (0x06b0ffec)
0xf7eea4e2 SDL_Init+0x399b2 in libtas.so: filds 0xc(%esi)

Please let me know if there is any more information I could gather that might help.

[clementgallet]

Current master version should work now (b407738).

Could you paste here a log of the audio API around the time the timeout messages appear? Runtime > Debug > Log to file and Runtime > Debug > Print Categories > Sound. The generated log file is located where the executable is, with the same name + .txt.

I expect the game stops sending audio samples for some reason, and it cannot recover from it because of libTAS's partial ALSA implementation.

Also, you could try disabling sound entirely (Sound > Disable).

[firebingo]

Thanks for the fix on master. Testing the game with sound disabled and Keep main first thread on seems to pretty much work as intended.

Here is the first frame that it starts logging the audio samples line with the sound logging on.

[libTAS f:5538] Thread 7052           return 3840
[libTAS f:5538] Thread 7052        snd_pcm_state call.
[libTAS f:5538] Thread 7052        snd_pcm_writei call with 480 frames
[libTAS f:5538] Thread 7051        Start mixing about 735 samples
[libTAS f:5538] Thread 7051        Audio mixing will underrun, waiting for the game to send audio samples
[libTAS f:5538] Thread 7052        snd_pcm_avail_update call.
[libTAS f:5538] Thread 7052           return 3360
[libTAS f:5538] Thread 7052        snd_pcm_state call.
[libTAS f:5538] Thread 7052        snd_pcm_writei call with 544 frames
[libTAS f:5538] Thread 7052        snd_pcm_writei call with 416 frames
[libTAS f:5538] Thread 7051        Start mixing source 1
[libTAS f:5538] Thread 7051          Buffer 8 is read from 160 to its end 416
[libTAS f:5538] Thread 7051          Buffer 2 in read in range 0 - 480
[libTAS f:5538] Thread 7051          Buffer 4 in read in range 0 - 64

And here is the last before it crashes.

[libTAS f:6003] Thread 7051        Start mixing about 735 samples
[libTAS f:6003] Thread 7051        Audio mixing will underrun, waiting for the game to send audio samples
[libTAS f:6003] Thread 7052        snd_pcm_avail_update call.
[libTAS f:6003] Thread 7052           return 3936
[libTAS f:6003] Thread 7052        snd_pcm_state call.
[libTAS f:6003] Thread 7052        snd_pcm_writei call with 480 frames
wine: Unhandled page fault on read access to 0000000C at address F7EF1505 (thread 002b), starting debugger..

I have also attached the full log file with error, warning, and sound on. touhou_luna_nights.exe.log.zip

[clementgallet]

Thanks for the log. The game provides audio samples as expected, filling the audio buffer with the right amount of samples, until frame 5501. From then, it sends exactly 544 and 416 samples on odd frames and 480 samples on even frames, which makes an average of 720 samples per frame. However, the audio device consumes 800 samples per frame, so the audio buffer is slowly being depleted. The game still queries for the available samples in the audio buffer, but does not seem to care about that value. Eventually, the audio buffer is empty, so libTAS waits (with timeout) for more samples.

Maybe the game is changing some audio settings that libTAS does not hook/support (e.g. input sample frequency). Could you make another log file, but you launch libTAS using WINEDEBUG=+alsa libTAS?

[firebingo]

Hello, Here is a new log file with WINEDEBUG=+alsa on. touhou_luna_nights.exe.log.zip

[firebingo]

Hello, I Just wanted to check and see if there had been any update on this issue. Thank you for the help.

[clementgallet]

I checked the log, but it doesn't show anything relevant. I need to test it myself

[firebingo]

Thank you. If you want any help with doing so let me know. It does require using a version with a dummy steam client as it is only available through steam.

[firebingo]

Hello, I came back to check this with the latest commits since it has been a while since I last tested it. Any commit from 7111f1f onward causes wine to crash on launch.

The log around the crash looks like this:

[libTAS f:0] Thread 22936 (main) Imported symbol glClear function : 0xf60ceb40
[libTAS f:0] Thread 22936 (main) glClear call.
[libTAS f:0] Thread 22936 (main) glDrawArrays call.
[libTAS f:0] Thread 22936 (main) Imported symbol glDrawArrays function : 0xf60d0280
[libTAS f:0] Thread 22936 (main) dlopen call with file <NULL>
terminate called after throwing an instance of 'std::logic_error'
  what():  basic_string::_M_construct null not valid
wine: Assertion failed at address F7FFD069 (thread 0009), starting debugger...
[libTAS f:0] Thread 22936 (main) Imported symbol dup2 function : 0xf7b6d2f0
[libTAS f:0] Thread 22936 (main) Imported symbol signal function : 0xf7ab3270
002c:fixme:dbghelp:elf_search_auxv can't find symbol in module

[clementgallet]

Sorry not the wait. That particular commit had a bug that was fixed in the next commit. It looks like the log you are displaying is caused by that bug. Could you test again with a later commit?

[firebingo]

Thank you for the reply. I have recently been running off commit eb7f5b7 and it has been working. The audio underflow issue is still happening and causing the game to skip badly after ~5000 frames or so. But one of the commits has prevented it from crashing due to this. I have not tested to see which one improved it though.

[firebingo]

Hello, Just to update on this since it has been a bit. Even with sound disabled the game seems to have some intermittent issues with its audio code that occasionally cause the game to crash. I will on occasion see ov_read errors with a code of -3 (OV_HOLE). These typically don't seem to cause a problem. But on rare occasion I will also get a ov_raw_seek error with a -137 code (OV_EBADLINK) that almost always causes the game to hard crash with no further messaging. I unfortunately have not found any consistent way to reproduce these. Sometimes I can work for an hour and not see a problem and sometimes it crashes after <100 frames of work from this. Reading the descriptions of the error codes though they may be related to the current known issue.

[firebingo]

Hello, Sorry for continuously posting on this. I spent some time testing other commits because I had been testing my previous comment on the latest commit (5e3fd79) and noticed that the Audio mixing will underrun issue does not occur on this commit. However this commit does cause the game to run significantly slower.