Logging to STDERR by libfmt makes the game crash

[pzhlkj6612]

Hello! I'm a newbee in C++ programming about ra2yr. Thanks for your effort for creating "ra2yrcpp" and "pyra2yr" projects.

TL;DR

The "libfmt" library does not work properly on my PC. Disabling all logging statements in "libra2yrcpp.dll" or writing logs to a file solves the problem, regardless of whether the library is debug or release build.

Environment

• OS: Windows 11 Pro 24H2
• Game: YR 1.001
• Spawner: CI build on https://github.com/CnCNet/yr-patches/commit/368ca1193c8143623f8c7bc1a1db0c23e8683a90

The Crash

Recently I tried to launch the game with "libra2yrcpp.dll" but failed. The game successfully loaded. I was able to see my MCV on the starting location and the money is 143. Then, the game exited without telling me anything.

The "client.log" file of CnCNet:

...
... Launch executable: ...\gamemd-spawn.ra2yr.exe
... Launch arguments: -SPAWN
... GameProcessLogic: Process started.
... Waiting for qres.dat or gamemd-spawn.ra2yr.exe to exit.
... 
... GameProcessLogic: Process exited.
... GameProcessExited: Parsing statistics.
...

Looks normally.

There were some logs in Windows Event Viewer, but they looked useless to me...

I've tried all "hardened/non-hardened" and "debug/release" spawners but still didn't work.

After some searching, I downloaded IDA Pro and WinDbg and had found something meaningful.

The Call Stack

I've built the debug DLL by CMAKE_BUILD_TYPE=Debug ./scripts/tools.sh docker-build. I just hoped that I can see more information in the debugger.

I was using the debug build spawner because I needed to pause the game during its loading ("Quick edit mode" [^1]).

[^1]: Windows 10 console stops running if I click in the console window - Super User | https://superuser.com/q/1442941

My steps were as follows:

1. Launched the game by CnCNet client. Left-clicked the CLI dialog of the spawner to pause the loading.
2. Launched WinDbg. Attached to the game process and entered g to continue the execution.
3. Right-clicked that CLI dialog to resume the loading.
4. WinDbg breaked the process. Entered k to see the call stack.

> k
 # ChildEBP RetAddr      
00 00e0c390 774829f4     ntdll!NtTerminateProcess+0xc
01 00e0c468 75ec9fa2     ntdll!RtlExitUserProcess+0x184
02 00e0c47c 76338017     KERNEL32!ExitProcessImplementation+0x12
03 00e0c488 763385bf     msvcrt!__crtExitProcess+0x17
04 00e0c4cc 76337fa1     msvcrt!doexit+0x135
05 00e0c4e0 7632d488     msvcrt!_exit+0x11
06 00e0c810 6f1a816c     msvcrt!abort+0xe8
WARNING: Stack unwind information not available. Following frames may be wrong.
07 00e0c8e0 6ef04c6b     libra2yrcpp!ExeRun+0x3c93f3
08 00e0cd20 6ef04d6e     libra2yrcpp!ExeRun+0x125ef2
09 00e0cf80 6efeca73     libra2yrcpp!ExeRun+0x125ff5
0a 00e0d0c0 6efed827     libra2yrcpp!ExeRun+0x20dcfa
0b 00e0d0f0 6ede2507     libra2yrcpp!ExeRun+0x20eaae
0c 00e0d140 6ede3b83     libra2yrcpp!ExeRun+0x378e
0d 00e0d180 6efee804     libra2yrcpp!ExeRun+0x4e0a
0e 00e0d1e0 6efeecca     libra2yrcpp!ExeRun+0x20fa8b
0f 00e0d230 6eddecc0     libra2yrcpp!ExeRun+0x20ff51
10 00e0d280 031e2011     libra2yrcpp!GameLoopBegin+0x3a
11 00e0f0a8 006be066     0x31e2011
12 00e0fee8 007cd8ef     gamemd_spawn_ra2yr+0x2be066
13 00e0ff74 75eb5d49     gamemd_spawn_ra2yr+0x3cd8ef
14 00e0ff84 774bbd6b     KERNEL32!BaseThreadInitThunk+0x19
15 00e0ffdc 774bbcf1     ntdll!__RtlUserThreadStart+0x2b
16 00e0ffec 00000000     ntdll!_RtlUserThreadStart+0x1b

Then, I opened IDA. I re-launched a new game and attached to it with IDA. I set a breakpoint in libra2yrcpp:

> bp libra2yrcpp!ExeRun+0x3c93f3
> bl
 0 e x86 00000000`6f1a816c     0001 (0001)  0:**** libra2yrcpp!ExeRun+0x3c93f3

The code was:

.text:6F1A816C loc_6F1A816C:                           ; CODE XREF: __gnu_cxx::__verbose_terminate_handler(void)+DF↑j
.text:6F1A816C                 mov     [esp+2Ch+lpmangled], edi ; Block

I continued the execution, and then successfully hit the breakpoint! I clicked the "RetAddr" of each frame to reveal the call stack:

> k
ChildEBP RetAddr      
WARNING: Stack unwind information not available. Following frames may be wrong.
00e0c8e0 6ef04c6b     libra2yrcpp!ExeRun+0x3c93f3     ; call    fmt::v9::detail::fwrite_fully(void const*,uint,uint,_iobuf *)
00e0cd20 6ef04d6e     libra2yrcpp!ExeRun+0x125ef2     ; call    fmt::v9::detail::print(_iobuf *,fmt::v9::basic_string_view<char>)
00e0cf80 6efeca73     libra2yrcpp!ExeRun+0x125ff5     ; call    fmt::v9::vprint(_iobuf *,fmt::v9::basic_string_view<char>,fmt::v9::basic_format_args<fmt::v9::basic_format_context<fmt::v9::appender,char>>)
00e0d0c0 6efed827     libra2yrcpp!ExeRun+0x20dcfa     ; call    ra2yrcpp::logging::print_message<int>(_iobuf *,ra2yrcpp::logging::Level,char const*,char const*,char const*,int,int)
00e0d0f0 6ede2507     libra2yrcpp!ExeRun+0x20eaae     ; call    ra2yrcpp::logging::eerror<char const*,char const*,char const*,int,int>(char const*,char const*,char const*,int,int)
00e0d140 6ede3b83     libra2yrcpp!ExeRun+0x378e       ; call    ra2::TypeClassParser::parse(void)
00e0d180 6efee804     libra2yrcpp!ExeRun+0x4e0a       ; call    ra2::parse_AbstractTypeClasses(google::protobuf::RepeatedPtrField<ra2yrproto::ra2yr::ObjectTypeClass> *,ra2::abi::ABIGameMD *)
00e0d1e0 6efeecca     libra2yrcpp!ExeRun+0x20fa8b     ; call    StateSave::state_to_protobuf(bool)
00e0d230 6eddecc0     libra2yrcpp!ExeRun+0x20ff51     ; call    StateSave::execute(void)
00e0d280 03282011     libra2yrcpp!GameLoopBegin+0x3a
...

So...

Libfmt Broke the Game?

I wanted to see those messages:

https://github.com/shmocz/ra2yrcpp/blob/1af2a459bee60417301450f9e95b4b795e17ad81/src/logging.hpp#L25-L36

diff --git a/src/logging.hpp b/src/logging.hpp
index 43cc69f..79caec3 100644
--- a/src/logging.hpp
+++ b/src/logging.hpp
@@ -26,6 +26,7 @@ template <typename... Args>
 inline void print_message(FILE* fp, Level level, const char* fmt_s,
                           const char* file, const char* func, int line,
                           Args... args) {
+  fp = fopen("libra2yrcpp.dll.stderr", "a");
   fmt::print(
       fp, "{}: [thread {} TS: {}]: {}:{}:{} {}\n",
       levels[static_cast<int>(level)],
@@ -33,6 +34,7 @@ inline void print_message(FILE* fp, Level level, const char* fmt_s,
       static_cast<std::uint64_t>(
           std::chrono::high_resolution_clock::now().time_since_epoch().count()),
       file, func, line, fmt::format(fmt_s, args...));
+  fclose(fp);
 }

Then the game was playable!!

The log in the "stderr" file was as follows:

INFO: [thread 1753268367 TS: 1737894946797726900]: /home/user/project/src/is_context.cpp:create_hook:192 name=TunnelSendTo,target=0x7b3d6f,size_bytes=6
DEBUG: [thread 1753268367 TS: 1737894946798151100]: /home/user/project/src/hook.cpp:patch_code:13 address=0x3016000, bytes=6
DEBUG: [thread 1753268367 TS: 1737894946798327500]: /home/user/project/src/hook.cpp:JumpTo:42 Trampoline size=6
...
DEBUG: [thread 2076165573 TS: 1737894946807120300]: /home/user/project/src/command/command_manager.hpp:worker:345 Spawn worker
DEBUG: [thread 1753268367 TS: 1737894946807579700]: /home/user/project/src/websocket_server.cpp:start:210 init asio, port=14521
ERROR: [thread 1753268367 TS: 1737894951060563400]: /home/user/project/src/ra2/state_parser.cpp:parse:246 unknown TypeClass: 10
...
ERROR: [thread 1753268367 TS: 1737894951062879400]: /home/user/project/src/ra2/state_parser.cpp:parse:246 unknown TypeClass: 28
...
ERROR: [thread 1753268367 TS: 1737894951063554100]: /home/user/project/src/ra2/state_parser.cpp:parse:246 unknown TypeClass: 14
...
ERROR: [thread 1753268367 TS: 1737894951065716900]: /home/user/project/src/ra2/state_parser.cpp:parse:246 unknown TypeClass: 32
...
<too many "unknown TypeClass" lines>
...

The library indeed wanted to write to STDERR, but why it crashed? I don't know. The official docs says that fmt::print(stderr is a usage: https://fmt.dev/9.1.0/api.html#_CPPv4IDpEN3fmt5printEvPNSt4FILEE13format_stringIDp1TEDpRR1T

Message "cannot write to file: Bad file descriptor"

I had seen this error when I commented out the eprintf() in TypeClassParser::parse() without other modification, the game was also playable, but some of my commands sent by pyra2yr got errors with the "cannot write to file: Bad file descriptor" message.

Slow Start and End of the Game if fopen("stderr", "w")

If I only changed the print_message() function like this:

diff --git a/src/logging.hpp b/src/logging.hpp
index 43cc69f..45f9f7f 100644
--- a/src/logging.hpp
+++ b/src/logging.hpp
@@ -26,6 +26,8 @@ template <typename... Args>
 inline void print_message(FILE* fp, Level level, const char* fmt_s,
                           const char* file, const char* func, int line,
                           Args... args) {
+  // fp = fopen("libra2yrcpp.dll.stderr", "a");
+  fp = fopen("stderr", "w");
   fmt::print(
       fp, "{}: [thread {} TS: {}]: {}:{}:{} {}\n",
       levels[static_cast<int>(level)],
@@ -33,6 +35,7 @@ inline void print_message(FILE* fp, Level level, const char* fmt_s,
       static_cast<std::uint64_t>(
           std::chrono::high_resolution_clock::now().time_since_epoch().count()),
       file, func, line, fmt::format(fmt_s, args...));
+  fclose(fp);
 }

The game was playable, but it stuck seconds during its start and end. No log was showed in the CLI dialog of the spawner.

[shmocz]

I've just updated fmtlib. Please re-test with the latest version to see if the issue persists.

The fp argument should already point to valid STDERR/STDOUT handle (see the eprintf, wrpintf etc. macros in logging.hpp). Slow performance is likely due to overhead from fopen/fclose. Also they are not thread safe and shouldn't be called inside print_message. fmt::print itself is thread safe, see: https://github.com/fmtlib/fmt/issues/1348#issuecomment-539717108

Regarding pyra2yr: it's currently broken and uses incorrect ra2yrproto and protobuf versions. Will update it ASAP.

[pzhlkj6612]

I've just updated fmtlib. Please re-test with the latest version to see if the issue persists.

I'll do it soon!

Slow performance is likely due to overhead from fopen/fclose.

Well, not really. fopen("libra2yrcpp.dll.stderr", "a") does not affect the performance, but fopen("stderr", "w") does.

Also they are not thread safe and shouldn't be called inside print_message.

Okay, thanks for the tip. I ignored thread-safe things when playing with this issue.

[pzhlkj6612]

Unfortunately, the crash persists.

I tried catching the exception thrown by fmt::print, then I got "cannot write to file: Bad file descriptor".

I don't know if the STDERR fd is abnormal on my Windows. I think I should go to test it in VMs (Windows7, 10 and 11).

[shmocz]

Are you able to run all the tests in the release zip file without issues? If you get errors about missing DLL's (they can't be included due to licensing reasons), try building with ./scripts/tools.sh docker-build and copy them from build output folder.

EDIT: changed build-cppto docker-build

[shmocz]

I'm in the midst of making the library compatible with yrpp-spawner and Syringe, and can now reproduce the crash on Linux+wine, but only if using Syringe (legacy CnCNet spawner works fine). The culprit is the eprintf inside TypeClassParser::parse.

https://github.com/shmocz/ra2yrcpp/blob/87dcf88af2e0b24c846cd242345c1b644f3c658d/src/ra2/state_parser.cpp#L247

Commenting that out fixes the problem. Other error/debug messages seem to work fine.

It might be that the earlier AbstractClass_WhatAmI call messes the stack/registers in a way that interferes with fmtlib's internal state, and for some reason this causes problems only on Windows or when using Syringe.

EDIT: The issue might be due to libra2yrcpp and game using different CRT: https://stackoverflow.com/questions/32617695/stdout-of-process-not-redirected-properly-via-dll-injection. With Linux+wine and legay spawner fmtlib picks a valid stderr handle, but on Windows or if injected, it'll be invalid. Interestingly, the library has been confirmed to work on Windows in the past using legacy spawner. I'm not sure what's gone wrong. Could be related to static linking of MinGW libraries: https://github.com/shmocz/ra2yrcpp/commit/2de7a29bd80a8e1efa76c533edfc987166881bb6 EDIT2: Other relevant discussion

[pzhlkj6612]

... The culprit is the eprintf inside TypeClassParser::parse. ...

Yes, it is. Don't know why other logs do not crash.

It might be that the earlier AbstractClass_WhatAmI call messes the stack/registers in a way that interferes with fmtlib's internal state

I've tested but have no proof.

... EDIT: The issue might be due to libra2yrcpp and game using different CRT: ... ...

Well, I managed to fix it without touching linkage stuff. The SetStdHandle in those links enlightened me! See #19.

Also:

• c# - Problem using AllocConsole() and marshalling - Stack Overflow https://stackoverflow.com/q/4349187
• Adding Console I/O to a Win32 GUI App https://web.archive.org/web/20070513064449/http://www.halcyon.com/~ast/dload/guicon.htm

.