TR1: Saving while music is playing causes a segfault on load

[absolutelynothinghere]

If I save the game while music is playing, then try to load the save file, the game segfaults.

I'm using the FLAC music pack linked in this repo. I went through all the FLAC files and determined that the problem happens when saving during tracks 02 to 20 (cinematic music) but not during tracks 57 to 60 (ambience / white noise). I have no idea why this problem happens with some FLAC files but not others.

Here are some save files that were created while music was playing, causing a segfault on load:

save_tr1_01.dat.gz save_tr1_05.dat.gz save_tr1_16.dat.gz

Note: I tested this on both the optimized and non-optimized builds of TR1X.

[rr-]

@absolutelynothinghere does TR1X.log contain any helpful information (for debug builds)?

[absolutelynothinghere]

Nothing helpful in the log unfortunately: TR1X.log
The terminal output matches the log, with an additional Segmentation fault line at the end.

debug builds

Could you kindly tell me how to create a debug build? I couldn't find any mention of that in the meson.build files.

Edit: are you talking about builds with libbacktrace?

[rr-]

Nothing helpful in the log unfortunately: TR1X.log The terminal output matches the log, with an additional Segmentation fault line at the end.

debug builds

Could you kindly tell me how to create a debug build? I couldn't find any mention of that in the meson.build files.

Edit: are you talking about builds with libbacktrace?

Correct. To create a debug build, we typically run just tr1-build-linux though which uses just command runner, similar to make. You can find more details on how to do this in Meson by consulting the justfile.

[absolutelynothinghere]

Alright, here's the backtrace output:

log_linux.c 36 M_SignalHandler == CRASH REPORT ==
log_linux.c 37 M_SignalHandler SIGNAL: 11
log_linux.c 38 M_SignalHandler STACK TRACE:
log_linux.c 29 M_StackTrace 0x01D5A11B: ???
log_linux.c 27 M_StackTrace 0x36BA923F: ??? (./signal/../sysdeps/unix/sysv/linux/x86_64/libc_sigaction.c:0)
log_linux.c 29 M_StackTrace 0x0157BC8E: ???
log_linux.c 29 M_StackTrace 0x0157C636: ???
log_linux.c 29 M_StackTrace 0x01D064FB: ???
log_linux.c 29 M_StackTrace 0x01433D72: ???
log_linux.c 29 M_StackTrace 0x0146AD03: ???
log_linux.c 29 M_StackTrace 0x01468798: ???
log_linux.c 29 M_StackTrace 0x014672C4: ???
log_linux.c 29 M_StackTrace 0x01402990: ???
log_linux.c 29 M_StackTrace 0x01404E33: ???
log_linux.c 29 M_StackTrace 0x01470A09: ???
log_linux.c 29 M_StackTrace 0x01485201: ???
log_linux.c 27 M_StackTrace 0x36B9420B: __libc_start_call_main (../sysdeps/nptl/libc_start_call_main.h:58)
log_linux.c 27 M_StackTrace 0x36B942BB: __libc_start_main_impl (../csu/libc-start.c:381)
log_linux.c 29 M_StackTrace 0x013F39F9: ???

[rr-]

It looks like the debug symbols are missing in this build. Maybe you could give the binary development snapshot from GitHub a try?

[absolutelynothinghere]

the debug symbols are missing

Sorry about that, I forgot a -s in the linker flags. The new log is below, let me know if anything is missing,

binary development snapshot

Unfortunately I cannot run it due to #1535

log_linux.c 36 M_SignalHandler == CRASH REPORT ==
log_linux.c 37 M_SignalHandler SIGNAL: 11
log_linux.c 38 M_SignalHandler STACK TRACE:
log_linux.c 27 M_StackTrace 0x01D5A0AB: M_SignalHandler (/tmp/TRX-tr1-4.5.1/src/libtrx/log_linux.c:41)
log_linux.c 27 M_StackTrace 0xB605C23F: ??? (./signal/../sysdeps/unix/sysv/linux/x86_64/libc_sigaction.c:0)
log_linux.c 29 M_StackTrace 0x0157BC1E: ???
log_linux.c 29 M_StackTrace 0x0157C5C6: ???
log_linux.c 27 M_StackTrace 0x01D0648B: Audio_Stream_SeekTimestamp (engine/audio_stream.c:689)
log_linux.c 27 M_StackTrace 0x01433D02: Music_SeekTimestamp (game/music.c:268)
log_linux.c 27 M_StackTrace 0x0146AC93: M_LoadCurrentMusic (game/savegame/savegame_bson.c:881)
log_linux.c 27 M_StackTrace 0x01468728: Savegame_BSON_LoadFromFile (game/savegame/savegame_bson.c:1380)
log_linux.c 27 M_StackTrace 0x01467254: Savegame_Load (game/savegame/savegame.c:428)
log_linux.c 27 M_StackTrace 0x01402920: Game_Start (game/game/game.c:81)
log_linux.c 27 M_StackTrace 0x01404DC3: GameFlow_InterpretSequence (game/gameflow.c:1057)
log_linux.c 27 M_StackTrace 0x01470999: Shell_Main (game/shell.c:218)
log_linux.c 27 M_StackTrace 0x01485191: main (specific/s_shell.c:314)
log_linux.c 27 M_StackTrace 0xB604720B: __libc_start_call_main (../sysdeps/nptl/libc_start_call_main.h:58)
log_linux.c 27 M_StackTrace 0xB60472BB: __libc_start_main_impl (../csu/libc-start.c:381)
log_linux.c 27 M_StackTrace 0x013F3989: ??? (/opt/zig-linux-x86_64-0.12.0/lib/libc/glibc/sysdeps/x86_64/start-2.33.S:120)

[rr-]

A quick solution might be to disable the load_current_music setting, but that might not address the root issue. If possible, could you compile ffmpeg with debug flags enabled? Alternatively, you might want to check if the time_base_sec is set to 0 or if the timestamp value seems reasonable (it should generally be in seconds). Thanks.

[absolutelynothinghere]

could you compile ffmpeg with debug flags enabled?

Sure thing, I compile all dependencies from source anyway. Here's the last part of the log after recompiling ffmpeg:

log_linux.c 36 M_SignalHandler == CRASH REPORT ==
log_linux.c 37 M_SignalHandler SIGNAL: 11
log_linux.c 38 M_SignalHandler STACK TRACE:
log_linux.c 27 M_StackTrace 0x01D5A02B: M_SignalHandler (/tmp/TRX-tr1-4.5.1/src/libtrx/log_linux.c:41)
log_linux.c 27 M_StackTrace 0x6699723F: ??? (./signal/../sysdeps/unix/sysv/linux/x86_64/libc_sigaction.c:0)
log_linux.c 27 M_StackTrace 0x0157BC12: ff_seek_frame_binary (libavformat/utils.c:2190)
log_linux.c 27 M_StackTrace 0x0157C5BA: seek_frame_internal (libavformat/utils.c:2481)
log_linux.c 27 M_StackTrace 0x0157C5BA: av_seek_frame (libavformat/utils.c:2504)
log_linux.c 27 M_StackTrace 0x01D0640B: Audio_Stream_SeekTimestamp (engine/audio_stream.c:689)
log_linux.c 27 M_StackTrace 0x01433CF2: Music_SeekTimestamp (game/music.c:268)
log_linux.c 27 M_StackTrace 0x0146AC83: M_LoadCurrentMusic (game/savegame/savegame_bson.c:881)
log_linux.c 27 M_StackTrace 0x01468718: Savegame_BSON_LoadFromFile (game/savegame/savegame_bson.c:1380)
log_linux.c 27 M_StackTrace 0x01467244: Savegame_Load (game/savegame/savegame.c:428)
log_linux.c 27 M_StackTrace 0x01402910: Game_Start (game/game/game.c:81)
log_linux.c 27 M_StackTrace 0x01404DB3: GameFlow_InterpretSequence (game/gameflow.c:1057)
log_linux.c 27 M_StackTrace 0x01470989: Shell_Main (game/shell.c:218)
log_linux.c 27 M_StackTrace 0x01485181: main (specific/s_shell.c:314)
log_linux.c 27 M_StackTrace 0x6698220B: __libc_start_call_main (../sysdeps/nptl/libc_start_call_main.h:58)
log_linux.c 27 M_StackTrace 0x669822BB: __libc_start_main_impl (../csu/libc-start.c:381)
log_linux.c 27 M_StackTrace 0x013F3979: ??? (/opt/zig-linux-x86_64-0.12.0/lib/libc/glibc/sysdeps/x86_64/start-2.33.S:120)

check if the time_base_sec is set to 0

I added a LOG_ERROR after every definition of time_base_sec in audio_stream.c and found that the value is always 0.000023. The full log is here:

TR1X.log

Just search for the string time_base_sec

[rr-]

It's unfortunate that, even with seemingly identical software versions and music files, I'm unable to replicate the issue. I can only speculate at this point, and my hypothesis is that we might be incorrectly using the FFmpeg APIs. The only questionable thing I was able to find, though, is that we hardcode the stream index to 0, which shouldn't be an issue since 1) we use the same music files 2) most of music files ship only with one stream. That being said, could you please try this patch?

diff --git a/src/libtrx/engine/audio_stream.c b/src/libtrx/engine/audio_stream.c
index 496f224e..03b4fc23 100644
--- a/src/libtrx/engine/audio_stream.c
+++ b/src/libtrx/engine/audio_stream.c
@@ -45,6 +45,7 @@ typedef struct {

     struct {
         AVStream *stream;
+        int32_t stream_idx;
         AVFormatContext *format_ctx;
         const AVCodec *codec;
         AVCodecContext *codec_ctx;
@@ -90,12 +91,12 @@ static void M_SeekToStart(AUDIO_STREAM_SOUND *stream)
         // reset to start of file
         avio_seek(stream->av.format_ctx->pb, 0, SEEK_SET);
         avformat_seek_file(
-            stream->av.format_ctx, -1, 0, 0, 0, AVSEEK_FLAG_FRAME);
+            stream->av.format_ctx, stream->av.stream_idx, 0, 0, 0, AVSEEK_FLAG_FRAME);
     } else {
         // seek to specific timestamp
         const double time_base_sec = av_q2d(stream->av.stream->time_base);
         av_seek_frame(
-            stream->av.format_ctx, 0, stream->start_at / time_base_sec,
+            stream->av.format_ctx, stream->av.stream_idx, stream->start_at / time_base_sec,
             AVSEEK_FLAG_ANY);
     }
 }
@@ -277,6 +278,7 @@ static bool M_InitialiseFromPath(int32_t sound_id, const char *file_path)
         AVStream *current_stream = stream->av.format_ctx->streams[i];
         if (current_stream->codecpar->codec_type == AVMEDIA_TYPE_AUDIO) {
             stream->av.stream = current_stream;
+            stream->av.stream_idx = i;
             break;
         }
     }
@@ -687,7 +689,7 @@ bool Audio_Stream_SeekTimestamp(int32_t sound_id, double timestamp)
         AUDIO_STREAM_SOUND *stream = &m_Streams[sound_id];
         const double time_base_sec = av_q2d(stream->av.stream->time_base);
         av_seek_frame(
-            stream->av.format_ctx, 0, timestamp / time_base_sec,
+            stream->av.format_ctx, stream->av.stream_idx, timestamp / time_base_sec,
             AVSEEK_FLAG_ANY);
         SDL_UnlockAudioDevice(g_AudioDeviceID);
         return true;

[absolutelynothinghere]

Sadly the patch does not fix the problem...

Which FFmpeg version are you using? I'm using 4.4.1 as per the Dockerfile.

[rr-]

4.4.1 as well. I was thinking that the issue might be related to multithreading, but even if the seeks happened from a different thread, the calls to SDL_LockAudioDevice should ensure atomic access.

[absolutelynothinghere]

The current behavior when loading a save file is opening a music track and seeking to a specific position in the track, is that correct?... If so, is there a way to open the music track without seeking? As in loading a save file starts playing the music track from the beginning.

[rr-]

The current behavior when loading a save file is opening a music track and seeking to a specific position in the track, is that correct?... If so, is there a way to open the music track without seeking? As in loading a save file starts playing the music track from the beginning.

I'm not sure if my message got lost, but to have the music track start from the beginning when you load a save file, you can adjust the load_current_music setting I mentioned earlier.

[rr-]

@absolutelynothinghere we have recently found and fixed another bug, which could also have affected this one. Could you please let me know if the latest development snapshot still exhibits this issue? Thanks!

[absolutelynothinghere]

@rr- Unfortunately the latest development branch does not fix the issue for me.