First call to spdlog crashes process in Windows Release build

[DavidRobb]

A rather weird one that I have investigated about as far as I can.

I have a simple C++ process that I would like to start from a Kotlin Desktop App.

The C++ is just

#include <iostream>

#include "spdlog/spdlog.h"

using namespace std;

int main(int argc, char *argv[])
{
    while (true)
    {
        cerr << "Read Settings 4 Timer update " << endl;
        spdlog::info("Timerd  update spdlog");
        this_thread::sleep_for(500ms);
    }

    return 0;
}

This C++ exe process is started from kotlin using:

    val serverPath = Paths.get("C:/prog/SpdLogTest/TimerLog/build/TimerLog.exe")

    try {
        val parts = listOf("cmd", "/C", "start", "\"MyTitle\"", "/wait", serverPath.toString())
        ProcessBuilder(parts)
            .directory(serverPath.parent.toFile())
            .start()
    } catch (e: IOException) {
        println("Start server exception")
        e.printStackTrace()
        return@application
    }

This crashes the process on the first call to spdlog but only if I build the C++ in Release mode and run the kotlin as runDistributable or runReleaseDistributable. If I build the C++ as Debug or run the Kotlin in the IDE as Run it works as expected.

Maybe some sort of timing issue / race condition?

I'm running on a 13th Gen Intel(R) Core(TM) i7-13700K 3.40 GHz under Windows 11 Pro using the Visual Studio Community 2022 Release compiler for amd64 kit. I've attached the CMake project for the C++ process. The Kotlin project can be created by going to https://www.jetbrains.com/help/kotlin-multiplatform-dev/compose-multiplatform-create-first-app.html and selecting just Desktop. Then paste the kotlin code above into the desktop main.kt just before the Window call.

Any ideas where to go form here?

SpdLogTest.zip

CMake config is

[proc] Executing command: chcp
[main] Configuring project: SpdLogTest 
[proc] Executing command: "C:\Program Files\Microsoft Visual Studio\2022\Community\Common7\IDE\CommonExtensions\Microsoft\CMake\CMake\bin\cmake.exe" -DCMAKE_BUILD_TYPE:STRING=Debug -DCMAKE_EXPORT_COMPILE_COMMANDS:BOOL=TRUE --no-warn-unused-cli -SC:/prog/SpdLogTest/TimerLog -Bc:/prog/SpdLogTest/build -G Ninja
[cmake] Not searching for unused variables given on the command line.
[cmake] -- The CXX compiler identification is MSVC 19.40.33813.0
[cmake] -- Detecting CXX compiler ABI info
[cmake] -- Detecting CXX compiler ABI info - done
[cmake] -- Check for working CXX compiler: C:/Program Files/Microsoft Visual Studio/2022/Community/VC/Tools/MSVC/14.40.33807/bin/Hostx64/x64/cl.exe - skipped
[cmake] -- Detecting CXX compile features
[cmake] -- Detecting CXX compile features - done
[cmake] -- Performing Test CMAKE_HAVE_LIBC_PTHREAD
[cmake] -- Performing Test CMAKE_HAVE_LIBC_PTHREAD - Failed
[cmake] -- Looking for pthread_create in pthreads
[cmake] -- Looking for pthread_create in pthreads - not found
[cmake] -- Looking for pthread_create in pthread
[cmake] -- Looking for pthread_create in pthread - not found
[cmake] -- Found Threads: TRUE  
[cmake] -- Configuring done (1.8s)
[cmake] -- Generating done (0.0s)
[cmake] -- Build files have been written to: C:/prog/SpdLogTest/build
[main] Configuring project: SpdLogTest 
[proc] Executing command: "C:\Program Files\Microsoft Visual Studio\2022\Community\Common7\IDE\CommonExtensions\Microsoft\CMake\CMake\bin\cmake.exe" -DCMAKE_BUILD_TYPE:STRING=Debug -DCMAKE_EXPORT_COMPILE_COMMANDS:BOOL=TRUE --no-warn-unused-cli -SC:/prog/SpdLogTest/TimerLog -Bc:/prog/SpdLogTest/build -G Ninja
[cmake] Not searching for unused variables given on the command line.
[cmake] -- Configuring done (0.0s)
[cmake] -- Generating done (0.0s)
[cmake] -- Build files have been written to: C:/prog/SpdLogTest/build

[DavidRobb]

I'm using spdlog 1.14.1 x64-windows from vcpkg

[tt4g]

-DCMAKE_BUILD_TYPE:STRING=Debug

As far as I can see from the log, the project is a debug build. spdlog crashes if it is a release build, because in C++, release builds and debug builds cannot be used together.

[tt4g]

It seems that vcpkg builds spdlog and fmt and generates spdlog.dll and fmt.dll (shared libraries), are these present in the library search path at runtime?

[DavidRobb]

The CMake log output was VS Code output for a Debug build. When selecting a release build the variables and appropriate dlls are all correct. The release and debug builds start fine run in a command window or even when run from

 cmd /c start "" /wait C:\prog\SpdLogTest\build\TimerLog.exe

It's just when the process is started from a jvm with ProcessBuilder that I get the problem

It works fine from the Kotlin multiplatform project when using
./gradle run
but the spdlog process crashes when using
./gradlew runDistributble
and then only with the Release build of the TimerLog.exe

I can only think that it is some incompatibility with how the ProcessBulder handles the IO streams and spdlog but I'm not really sure what to try next.

https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/ProcessBuilder.html

I've tried various combinations of

            .redirectOutput(ProcessBuilder.Redirect.INHERIT)
            .redirectError(ProcessBuilder.Redirect.INHERIT)

with Redirect PIPE, INHERIT or DISCARD but nothing seems to work for me.

[tt4g]

The release and debug builds start fine run in a command window or even when run from

Release and debug builds cannot be used together.
This is because the memory alignment of the structures is different and the MSVC runtime is different.
If it is working, then and only then will the environment be different.

I can't even isolate the problem due to using vcpkg and Kotlin.
If the problem occurs when building spdlog directly using CMake, then it may be a spdlog related problem. Otherwise, you should consider it a vcpkg or Kotlin problem.

[DavidRobb]

OK. Maybe I wasn't being clear. I use VS Code with Cmake to build a release build or a debug build of TimerLog.exe. Changing the config wipes the previous build files and re-creates the apropriate exe and dlls. It's this output that I referred to as Release or Debug for the C++ process. Both the Release and Debug versions work fine stand alone or even when started using the same mechanism as ProcessBuilder i.e. cmd /c start "" /wait C:\prog\SpdLogTest\build\TimerLog.exe

The kotlin / Java jvm is required because the issue is down to the incompatibility of the ProcessBuilder started process with spdlog but then only when built as Release and a kotlin ReleaseDistribution. I guess it is something to do with the way the input, output and error streams are plumbed through to the process but don't really know where to look.

I can try using the latest header only spdlog to take vcpkg out of the equation.

[tt4g]

Thank you for your detailed explanation. I understand the situation very well. Thank you.

Then we should consider that there is a problem with ProcessBulder.
Are all the .dlls and .exe in the same directory?
If they are in separate directories, the .exe may be crashing because it can't find the .dll.

See also;

• Dynamic-link library search order - Win32 apps | Microsoft Learn
• Is it possible to add a directory to DLL search path from a batch file or cmd script? - Stack Overflow

And ProcessBuilder#directory() is the working directory of cmd, while start is running in another working directory.

See:

• use cmd.exe to change directory and run command in that directory - Stack Overflow

[tt4g]

Other means of isolating the cause that I can think of are as follows:

• Check environment variables

  You might also want to check the environment variable Map returned by ProcessBuilder#environment() just to be sure.
  If for some reason you are not getting the environment variable from Kotlin (for example, the PATH environment variable is empty), then you can determine that this is the reason that the .exe is not running.

• Try executing a built-in command

  Run Windows built-in commands (dir and echo) instead of .exe.
  If these commands also crash, then Kotlin may not be able to launch the process from the ProcessBuilder.

  -val parts = listOf("cmd", "/C", "start", "\"MyTitle\"", "/wait", serverPath.toString())
  +val parts = listOf("echo", "test")

• Stop redirecting output

  STDOUT,STDERR redirects from the process may be causing the problem.
  Java uses UTF-16 as the internal character encoding in String.
  However, Windows cmd changes the character encoding according to the OS locale, so the difference in character encoding between the two processes may be causing the crash.

[DavidRobb]

OK Thanks for the suggestions:

Environment variables.
I don't think the process relies on anything. I've added a call to .environment().clear() and that doesn't change anything. i.e. still runs if I don't call spdlog, crashes if I do.

Built in commands work OK as does the TimerLog process with calls to std::cout instead of spdlog.
I added a call to Beep( 750, 100 ); in the main loop to hear a beep after every half second. Doing this allows me to call the exe directly (without a console window) and hear that it is executing. Same symptoms: works without spdlog but crashes with it.

Stop redirecting output.
Not sure how to do this. I have tried Redirect PIPE, INHERIT or DISCARD on output and error or not calling anything although I think this defaults to PIPE.

I shall try spdlog built from headers as I guess this gets round the need for spdlog.dll and fmt.dll to be present and loadable.

[tt4g]

I don't think the process relies on anything. I've added a call to .environment().clear() and that doesn't change anything. i.e. still runs if I don't call spdlog, crashes if I do.

I was thinking, contrary to you, that Kotlin may not be getting the environment variables of the current process correct.

This is because the ProcessBuilder.html#environment() documentation mentions some environment-dependent issues.

https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/ProcessBuilder.html#environment()

If the system does not support environment variables, an empty map is returned.

The returned map does not permit null keys or values. Attempting to insert or query the presence of a null key or value will throw a NullPointerException. Attempting to query the presence of a key or value which is not of type String will throw a ClassCastException.

The behavior of the returned map is system-dependent. A system may not allow modifications to environment variables or may forbid certain variable names or values. For this reason, attempts to modify the map may fail with UnsupportedOperationException or IllegalArgumentException if the modification is not permitted by the operating system.

Since the external format of environment variable names and values is system-dependent, there may not be a one-to-one mapping between them and Java's Unicode strings. Nevertheless, the map is implemented in such a way that environment variables which are not modified by Java code will have an unmodified native representation in the subprocess.

The returned map and its collection views may not obey the general contract of the Object.equals(java.lang.Object) and Object.hashCode() methods.

The returned map is typically case-sensitive on all platforms.

If a security manager exists, its checkPermission method is called with a RuntimePermission("getenv.*") permission. This may result in a SecurityException being thrown.

When passing information to a Java subprocess, system properties are generally preferred over environment variables.

[tt4g]

Not sure how to do this. I have tried Redirect PIPE, INHERIT or DISCARD on output and error or not calling anything although I think this defaults to PIPE.

You can DISCARD or redirect command output to NUL device (on Windows, NUL).

See: https://stackoverflow.com/questions/55628999/java-processbuilder-how-to-suppress-output-instead-of-redirecting-it

[tt4g]

You may try Runtime.getRuntime().exec() to see if the process starts.
If the process does not crash, then it is a ProcessBuilder bug.

val process = Runtime.getRuntime().exec("cmd /C start", \"MyTitle\" \"C:/prog/SpdLogTest/TimerLog/build/TimerLog.exe\"");

[DavidRobb]

OK. I've taken a snapshot of the spdlog repository head and rebuilt TimerLog.exe using headers only to overcome any dll issues.

I've also tried:
Runtime.getRuntime().exec("cmd /C start "MyTitle" "C:/prog/SpdLogTest/build/TimerLog.exe"");

I'm still getting exactly the same symptoms. i.e. fails with Release TimerLog.exe and createDistributable ProcessBldrTest. It works fine with any other combinations containing one of, i.e. No usage of spdlog, OR Debug build of TimerLog.exe OR ./gradlew run ProcessBldrTest.

No I have the spdlog source code, I'll try adding some printf to see if I can isolate what is causing the incompatibility.

Thanks for your help so far.

[DavidRobb]

Some progress. It is failing when it tries to acquire the lock at line 56 of wincolor_sink-in.h in the subroutine below:

template <typename ConsoleMutex>
void SPDLOG_INLINE wincolor_sink<ConsoleMutex>::log(const details::log_msg &msg) {
    if (out_handle_ == nullptr || out_handle_ == INVALID_HANDLE_VALUE) {
        return;
    }

    std::lock_guard<mutex_t> lock(mutex_);
    msg.color_range_start = 0;
    msg.color_range_end = 0;
    memory_buf_t formatted;
    formatter_->format(msg, formatted);
    if (should_do_colors_ && msg.color_range_end > msg.color_range_start) {
        // before color range
        print_range_(formatted, 0, msg.color_range_start);
        // in color range
        auto orig_attribs =
            static_cast<WORD>(set_foreground_color_(colors_[static_cast<size_t>(msg.level)]));
        print_range_(formatted, msg.color_range_start, msg.color_range_end);
        // reset to orig colors
        ::SetConsoleTextAttribute(static_cast<HANDLE>(out_handle_), orig_attribs);
        print_range_(formatted, msg.color_range_end, formatted.size());
    } else  // print without colors if color range is invalid (or color is disabled)
    {
        write_to_file_(formatted);
    }
}

If I comment this line out (obviously not appropriate as a workaround) it all works fine.
Any idea how to do a proper fix?

[tt4g]

Hmmm, if std::mutex is the cause of the crash, it may be the same problem as #3145.
MSVC2022 had a breaking change in std::mutex in the compiler and runtime.

See:

• VCRuntime incompatibility with older version in mutex code microsoft/STL#4730
• windows - First std::mutex::lock() crashes in application built with latest Visual Studio 2022 - Stack Overflow

However, this problem is 100% reproducible, and it is odd that it only crashes when the process is run from Kotlin.

[DavidRobb]

You're a star!!!
Defining the _DISABLE_CONSTEXPR_MUTEX_CONSTRUCTOR fixes it.

Yes, strange that it only manifested with a specific set of conditions, but I've tested with and without a few times now and it does appear fixed.

I'm sure this esoteric bug must be causing all sorts of hard to diagnose problems out there.

Thanks again for your help. spdlog is my goto logging library for C/C++. I love the simplicity of the fmt library too.

[tt4g]

Oh, I had no idea that was the cause. Anyway I'm glad your problem is solved.

[DavidRobb]

A bit more explanation as to why it fails only with ./gradlew runDistribution and works as standalone:

This gradle taks packages the whole Kotlin App with a JVM and all the necessary dlls to run independently on its own. This includes an out of date version of the MS VC redistributable dlls, in my case MSVCP140.dll v 14.29.30135.0. In order to run without the _DISABLE_CONSTEXPR_MUTEX_CONSTRUCTOR you need the latest version of the MS VC redistributables, currently version 14.40.33816.0.

I'll try updating my Java JDK and see if it fixes it without requiring the compiler flag.

[DavidRobb]

Can't find a JDK that packages the latest VC redistributables. :-(
I've raised a support request.
Happy for you to close this issue though. Thanks for your help

[DavidRobb]

Raised as JDK bug:

https://bugs.java.com/bugdatabase/view_bug?bug_id=JDK-8342299