FileXT causes Arma3 main thread to stall

[uniflare]

Looks like FileXT is filling the stderr buffer which, at least on windows, when it is full causes the main thread to stall on Arma3 (nothing is emptying/reading the buffer).

Server Details:

Executable Arguments:
    -port=2402
    -config=C:\Servers\UserApplications\User1\Arma3Master\Servers\_f0d1487932d447079feb7b4fcef5441f\server_config.cfg
    -cfg=C:\Servers\UserApplications\User1\Arma3Master\Servers\_f0d1487932d447079feb7b4fcef5441f\server_basic.cfg
    -profiles=C:\Servers\UserApplications\User1\Arma3Master\Servers\_f0d1487932d447079feb7b4fcef5441f
    -name=_f0d1487932d447079feb7b4fcef5441f
    -enableHT
    -netlog

Mods:
    @ace
    @Advanced_Rappelling__Reworked
    @Advanced_Sling_Loading
    @Advanced_Towing
    @BackpackOnChest
    @CBA_A3
    @CUP_Terrains__Core
    @CUP_Terrains__CWA
    @CUP_Terrains__Maps
    @CUP_Terrains__Maps_2_0
    @CUP_Units
    @CUP_Vehicles
    @CUP_Weapons
    @DUI__Squad_Radar
    @Enhanced_Movement
    @Hatchet_Framework__Development_Version
    @Jbad
    @LAMBS_Danger_fsm
    @LAMBS_Suppression
    @Lesh_s_Towing_Mod
    @LYTHIUM
    @Project_OPFOR
    @RHSAFRF
    @RHSGREF
    @RHSUSAF
    @RKSL_Studios__Attachments_v3_02
    @Task_Force_Arrowhead_Radio_BETA__
    @Zeus_Enhanced
    @TGP_Simple_Cockpit_Slew
    @Hatchet_H_60_pack__Development_Version
    @RHSSAF
    @ACE_Compat__RHS_AFRF
    @ACE_Compat__RHS_USAF
    @ACE_Compat__RHS_GREF
    @Anrop_Jbad_Legacy_Compatibility
    @Enhanced_Movement_Rework
    @Zeus_Enhanced__ACE3_Compatibility
    @ACE_Compat__RHS_SAF
    @3CB_BAF_Equipment
    @3CB_BAF_Units
    @3CB_BAF_Units_ACE_compatibility_
    @3CB_BAF_Units_RHS_compatibility_
    @3CB_BAF_Vehicles
    @3CB_BAF_Vehicles_RHS_reskins_
    @3CB_BAF_Vehicles_Servicing_extension_
    @3CB_BAF_Weapons
    @3CB_BAF_Weapons_RHS_ammo_compatibility_
    @3CB_Factions

Server Mods:
    @FileXT

System Specs:
    Windows Server 2022 Standard 64-bit (10.0, Build 20348) (20348.fe_release.210507-1500)
    12th Gen Intel(R) Core(TM) i3-12100F (8 CPUs), ~3.3GHz
    16384MB RAM + 28495MB Page File
    DirectX 12

Call Stack:

    ntdll.dll!00007fffdf8aeff4()    Unknown
    KernelBase.dll!00007fffdce04e2b()   Unknown
>   filext_x64.dll!write_text_ansi_nolock(const int fh, const char * const buffer, const unsigned int buffer_size) Line 443 C++
    filext_x64.dll!_write_nolock(int fh, const void * buffer, unsigned int buffer_size, __crt_cached_ptd_host & ptd) Line 710   C++
    filext_x64.dll!_write_internal(int fh, const void * buffer, unsigned int size, __crt_cached_ptd_host & ptd) Line 65 C++
    filext_x64.dll!__acrt_stdio_flush_nolock(_iobuf * public_stream, __crt_cached_ptd_host & ptd) Line 241  C++
    filext_x64.dll!__acrt_stdio_end_temporary_buffering_nolock(bool flag, _iobuf * public_stream, __crt_cached_ptd_host & ptd) Line 135 C++
    [Inline Frame] filext_x64.dll!__acrt_stdio_temporary_buffering_guard::{dtor}() Line 469 C++
    filext_x64.dll!common_vfprintf::__l2::<lambda>() Line 48    C++
    filext_x64.dll!__crt_seh_guarded_call<int>::operator()<void <lambda>(void),int <lambda>(void) &,void <lambda>(void)>(__acrt_lock_stream_and_call::__l2::void <lambda>(void) && setup, common_vfprintf::__l2::int <lambda>(void) & action, __acrt_lock_stream_and_call::__l2::void <lambda>(void) && cleanup) Line 202   C++
    [Inline Frame] filext_x64.dll!__acrt_lock_stream_and_call(_iobuf * const) Line 297  C++
    [Inline Frame] filext_x64.dll!common_vfprintf(const unsigned __int64 options, _iobuf * const stream, const char * const format, __crt_cached_ptd_host & arglist, char * const) Line 37  C++
    filext_x64.dll!__stdio_common_vfprintf(unsigned __int64 options, _iobuf * stream, const char * format, __crt_locale_pointers * locale, char * arglist) Line 61  C++
    [Inline Frame] filext_x64.dll!_vfprintf_l(_iobuf * const) Line 645  C++
    filext_x64.dll!fprintf(_iobuf * const _Stream, const char * const _Format, ...) Line 844    C++
    filext_x64.dll!RVExtensionArgs(char * output, int outputSize, const char * function, const char * * argv, int argc) Line 165    C++
    arma3server_x64.exe!00007ff757357874()  Unknown
    arma3server_x64.exe!00007ff7573575ba()  Unknown
    arma3server_x64.exe!00007ff757181f72()  Unknown
    arma3server_x64.exe!00007ff7580b8efa()  Unknown
    arma3server_x64.exe!00007ff7580b7c9c()  Unknown
    arma3server_x64.exe!00007ff7580c4a6d()  Unknown
    arma3server_x64.exe!00007ff757c258ff()  Unknown
    arma3server_x64.exe!00007ff757c1ffd1()  Unknown
    arma3server_x64.exe!00007ff75816a40c()  Unknown
    arma3server_x64.exe!00007ff758150526()  Unknown
    arma3server_x64.exe!00007ff758154295()  Unknown
    arma3server_x64.exe!00007ff7581735b0()  Unknown
    arma3server_x64.exe!00007ff7582462d0()  Unknown
    kernel32.dll!00007fffdef04ed0() Unknown
    ntdll.dll!00007fffdf88e39b()    Unknown

Pull Request to fix and refactor logging mechanism: #9

[uniflare]

I should add, this only started happening recently. My cause is a guess using my limited knowledge of how windows stderr pipes work - it seems to be the logical conclusion. Perhaps the Arma3 executable was piping stderr before on windows, but not anymore for some reason? (or another mod I was using was doing so, and stopped in a recent update).

Eitherway, it appears stderr piping on Windows cannot be relied upon in this manner. On Windows, I would reccomend maybe OutputDebugString to output directly to MSVC output window.

[Sparker95]

Hi, thanks. That's super weird. I have never touched any of stderr, and as for my knowledge I shouldn't if I am just making a simple dll. Is there any solid repro for this? When does it happen? During saving of vindicta game state?

[Sparker95]

Oh I see, @xoorath you have redirected logs to stderr, I failed to notice it. So this might be interesting for you :) I will check the PR later. Tbh I never used stderr and I am not entirely sure how this stream is supposed to work at all in C++ :D . I will need to do a bit of study first.

[uniflare]

Hey, thanks for the reply.

I could be wrong ofcourse, I have not tried reading stderr to see if it allows the process to continue, however generally, a pipe has a buffer in the CRT, and then the kernel has another buffer. If you fill a pipe buffer - kernel and CRT - then the next write will wait until someone reads from the pipe (effectively clearing space for more data).

On Linux, this may not be an issue, since you are always using the terminal, which consumes the std pipes automatically. However on windows, this doesn't seem to be the case right now on Arma (a Window doesn't consume these pipes automatically, something has to be written to consume these pipes).

I can repro this 100% everytime on our server, if I use default FileXT binaries (which appears to log to stderr pipe). With the PR change, it no longer hangs.

This will hang after a few saves in our KO Liberation server, on extension call to save. Though it can hang technically on any stderr fprintf that ends up filling the buffer.

--

If you would like to repro, you could probably repro easily by continually calling an extension function, that simply write a lot of data to the stderr pipe.

[Sparker95]

Oh, so you are using it for non-vindicta? I guess it's first usage outside of our mod then :)

[uniflare]

Yes - our group played quite a bit of Vindicta and just trying new things :). This is a useful mod, I made a similar mod myself years ago but having one cleaner and maintained by someone else is obviously much easier for me :D.

So I appreciate you sharing your hard work.

[uniflare]

I setup a HyperV Debian server and I didn't noticed any issues. Although on both windows and linux the messages aren't logged properly (PR pending #12 ).

[xoorath]

Hey, I haven't been around to check this out - thanks a lot for looking into this. I didn't expect that to be a problem, I learned something new.