spdlog::set_pattern only effective within the current cpp file

[alex-lt-kong]

My project is roughly structured like this:

1. main.cpp: the entry point that spawns many threads;
2. instance.cpp: the class/method which will be executed in separate threads.

I #include <spdlog/spdlog.h> in both of them and I log by calling spdlog::info()/spdlog::error()/etc only, without creating custom loggers.

The issue is, on some computers, I only need to call spdlog::set_pattern() once (at the very beginning of main() in main.cpp, before any instance threads are created), in main.cpp and all the log will be in the format I set. On some other computers, I need to call spdlog::set_pattern() in both main.cpp and instance.cpp to make the new logging pattern effective. If I only call spdlog::set_pattern() in main.cpp, then the log from main.cpp will use the new format, but logs from instance.cpp will still use the default format.

So the question is, why is this? Is it that I should always call spdlog::set_pattern() in each file? Or does it have anything to do with thread-safety ,etc?

[tt4g]

If it is a Windows machine using DLL, the reason is that the memory space is different between the DLLs and the application. Since spdlog::set_pattern() effects the default logger created for each memory space, please pass the default logger from main.cpp to instance.cpp. See also: https://github.com/gabime/spdlog/wiki/How-to-use-spdlog-in-DLLs

[tt4g]

Or does it have anything to do with thread-safety ,etc?

spdlog::set_pattern() is thread-safe. spdlog::set_pattern() calls logger::logger::set_pattern(). This API iterates over the sink container and performs read operations only. It is thread-safe as long as no write operations are performed to the sink container.

https://github.com/gabime/spdlog/blob/040874224bff7d61a09cbdb22fa318cbaf05afd7/include/spdlog/logger-inl.h#L82-L105

See also: https://github.com/gabime/spdlog/wiki/1.1.-Thread-Safety

[alex-lt-kong]

Hi @tt4g , sorry I did not explain my case clear enough, let me supplement a bit:

1. I use Debian stable (bullseye) only, so there is not Windows DLL

2. I don't deploy binary files. I compile on each computer where my program is used.

3. But still, on some Debian computers, I compile my program and spdlog::set_pattern() needs to be called once in main.cpp and it is effective everywhere. On some other computers, also Debian, I have to call spdlog::set_pattern() in both main.cpp and instance.cpp

4. I am aware of the below:

   Whenever the user calls set_pattern("..") the library "compiles" the new pattern to an internal efficient representation - This way the performance stays excellent even with complex patterns (no re-parsing of the pattern on each log call).

Does this mechanism seem to play a role in my issue?

[tt4g]

Does this mechanism seem to play a role in my issue?

I don't believe it is related.

Note that spdlog::set_pattern() is thread-safe, but it is the responsibility of sink to ensure that sinks called from it are thread-safe. Is sink thread safe? (In other words, is sink's name suffix _mt?)

Tip If the default logger has not been changed, sink is thread-safe.

https://github.com/gabime/spdlog/blob/040874224bff7d61a09cbdb22fa318cbaf05afd7/include/spdlog/details/registry-inl.h#L37-L49

Note also that if you change the default logger or sink after calling spdlog::set_pattern(), the formatter will not change unless you call spdlog::initialize_logger().

[alex-lt-kong]

Emmm...I just noticed something else. In main.cpp, I fisrtly call spdlog::set_pattern(), then I register a signal handler with register_signal_handlers() in the same thread:

void signal_handler(int signum) {
    if (signum == SIGPIPE) {    
        return;
    }
    spdlog::warn("Signal: {} caught, all threads will quit gracefully", signum);
    app.stop();
}

void register_signal_handlers() {
    struct sigaction act;
    act.sa_handler = signal_handler;
    sigemptyset(&act.sa_mask);
    act.sa_flags = SA_RESETHAND;
    if (sigaction(SIGINT, &act, 0) + sigaction(SIGABRT, &act, 0) +
        sigaction(SIGTERM, &act, 0) + sigaction(SIGPIPE, &act, 0) < 0) {
        throw runtime_error("sigaction() called failed, errno: " +
            to_string(errno));
    }
}

int main() {
    spdlog::set_pattern();
    register_signal_handlers();
...
}

When a signal is emitted, my signal_handler() will be invoked. I do some logging here as well. The issue is, when my signal_handler() is invoked, my pattern set by spdlog::set_pattern() is ineffective either.

It would be odd to suggest that I should also call spdlog::set_pattern() in signal_handler().

Any thought?

[tt4g]

Do not call the spdlog API in the signal handler. The signal handler code is executed by a special task given privileges by the OS. Your application process and threads continue to run while the signal handler is executing. However, the operation of most C++ APIs is not guaranteed, and protection by critical sections with thread-safe APIs is also undefined behavior.

The only APIs that can be safely called are those listed on std::signal - cppreference.com. These are called signal-safe functions because they are APIs that can be safely invoked in signal handler.

If you want to call a non-signal-safe API when a signal is received, provide an atomic variable that records that a signal was received, so that the callback is called when that variable changes.

See also: https://github.com/gabime/spdlog/issues/1607#issuecomment-794657339

[alex-lt-kong]

Thanks @tt4g , can I conclude the following?:

1. Even without dll, it may be the case that we need to call spdlog::set_pattern() in each.cpp file.
2. spdlog::whatever() shouldn't be directly used in a signal handler.

[gabime]

Even without dll, it may be the case that we need to call spdlog::set_pattern() in each.cpp file.

I don't think so.

[tt4g]

Even without dll, it may be the case that we need to call spdlog::set_pattern() in each.cpp file.

It does not seem to be related to this issue. The cause is undefined behavior due to a non-signal-safe API call in signal handler.

[alex-lt-kong]

The signal handler issue and the separate file/thread issue are two things. Let's mark the signal handler one as solved as I inadvertently triggered UB. The main issue I face is the one I said in the very original post, I have to call spdlog::set_pattern() in two files main.cpp and instance.cpp, to make my format effective.

As I supplemented in the subsequent post, I never use Windows and DLL, I compile my program on each machine (all Debian).

Given this scenario, any thoughts?

[tt4g]

Have you checked the operation of your application after avoiding the undefined behavior of the signal handler? C++ compilers generate code that developers do not expect when they optimize code that contains undefined behavior.

See "UB and optimization" section: Undefined behavior - cppreference.com

[alex-lt-kong]

I commented out the signal handler part altogether, the issue persists--in instance.cpp, if I don't call spdlog::set_pattern(), the new pattern will not be effective in instance.cpp.

Any thoughts?

Just in case it is relevant: my thread model is a bit convoluted like below. The idea is that we wrap the threading part in a class, my concrete instance will inherit this framework class and implement the method InternalThreadEntry(), which is essentially an infinite loop. The benefit of doing it this way is in my event loop, I can run it in a separate thread while still keeping the *this pointer.:

• instance.cpp

  
  class MyEventLoopThread {
  public:
  MyEventLoopThread() {}
  virtual ~MyEventLoopThread() {}
  
  void StartInternalEventLoopThread() {
      if (pthread_create(&_thread, NULL,
          InternalThreadEntryFunc, this) != 0) {
          throw runtime_error("pthread_create() failed, errno: " +
              to_string(errno));
      }
  }
  
  void StopInternalEventLoopThread() {
      _internalThreadShouldQuit = true;
  }
  
  void WaitForInternalEventLoopThreadToExit() {
      pthread_join(_thread, NULL);
  }

protected: /* Implement this method in your subclass with the code you want your thread to run. / virtual void InternalThreadEntry() = 0; bool _internalThreadShouldQuit = true;

private: static void InternalThreadEntryFunc(void This) { ((MyEventLoopThread *)This)->InternalThreadEntry(); return NULL; } pthread_t _thread = 0; };

* `main.cpp`:
```C++
Instance myIns = Instance(); // Instance inherits MyEventLoopThread
myIns.StartInternalEventLoopThread();
myIns.WaitForInternalEventLoopThreadToExit();

(If you failed to spot any issue in this sort of pseudocode, I can try to prepare a minimal reproducible example later)

[tt4g]

The spdlog API does not appear, so nothing can be determined from the code provided. Wait for the minimum code that can reproduce the problem.

[alex-lt-kong]

Hi @tt4g, the minimal reproducible example can be found here. As it is in a subdirectory of a repo, you may need to clone the entire repo to use it (but after clone you can remove everything not in this directory).

I tested it on Debian 11, with gcc 10.2.1. To compile:

mkdir build
cd build
cmake ../
make

To run:

./cs

The output I can see:

./mre/build$ ./cs 
2023-03-24T10:02:28.952+08:00|290652|    info| cs started
[2023-03-24 10:02:28.952] [info] from thread: 0
[2023-03-24 10:02:28.952] [info] from thread: 1
2023-03-24T10:02:28.952+08:00|290652|    info| 3 threads started
[2023-03-24 10:02:28.952] [info] from thread: 2
[2023-03-24 10:02:29.452] [info] from thread: 0
[2023-03-24 10:02:29.452] [info] from thread: 1
[2023-03-24 10:02:29.452] [info] from thread: 2
[2023-03-24 10:02:29.952] [info] from thread: 0
[2023-03-24 10:02:29.952] [info] from thread: 2
[2023-03-24 10:02:29.952] [info] from thread: 1
[2023-03-24 10:02:30.453] [info] from thread: 2
[2023-03-24 10:02:30.453] [info] from thread: 1
[2023-03-24 10:02:30.453] [info] from thread: 0

So you can see from main thread the log had expected format but from worker threads the format is still the default one.

Please let me know if you face any difficulty compiling/running it.

[tt4g]

I don't have a Debian 11 machine so I will try it with Docker when I have time. By the way, do we need OpenCV and Crow in this project? If I exclude them, will the problem stop reproducing?

[alex-lt-kong]

Hi @tt4g , sorry, the previous version isn't really as "minimal" as it should be. I update it, removing tons of unused references, etc. The link is still the same above here.

I also tested the code with Clang 14.0.6:

./the-nitty-gritty/mre/build # cmake ../
-- The C compiler identification is Clang 14.0.6
-- The CXX compiler identification is Clang 14.0.6
-- Detecting C compiler ABI info
-- Detecting C compiler ABI info - done
-- Check for working C compiler: /usr/bin/clang - skipped
-- Detecting C compile features
-- Detecting C compile features - done
-- Detecting CXX compiler ABI info
-- Detecting CXX compiler ABI info - done
-- Check for working CXX compiler: /usr/bin/clang++ - skipped
-- Detecting CXX compile features
-- Detecting CXX compile features - done
-- Performing Test CMAKE_HAVE_LIBC_PTHREAD
-- Performing Test CMAKE_HAVE_LIBC_PTHREAD - Success
-- Found Threads: TRUE  
-- Configuring done
-- Generating done
-- Build files have been written to: /root/repos/the-nitty-gritty/mre/build

The result is still the same:

./the-nitty-gritty/mre/build # ./cs 
2023-03-24T12:59:05.177+08:00| 2464|    info| cs started
2023-03-24T12:59:05.177+08:00| 2464|    info| 3 threads started
[2023-03-24 12:59:05.177] [info] from thread: 2
[2023-03-24 12:59:05.177] [info] from thread: 0
[2023-03-24 12:59:05.177] [info] from thread: 1
[2023-03-24 12:59:05.677] [info] from thread: 2
[2023-03-24 12:59:05.677] [info] from thread: 0
[2023-03-24 12:59:05.677] [info] from thread: 1

Besides, as the MRE doesn't contain any POSIX/Linux system call, i sort of think it should compile on Windows as well (tho I never try)

[tt4g]

I forked your project (https://github.com/tt4g/the-nitty-gritty) and built only the mre/src /camera-server/CMakeLists.txt in a Docker container, but could not reproduce it.

Build log

```shell $ mkdir build $ cd build/ $ cmake .. -- The CXX compiler identification is GNU 10.2.1 -- Detecting CXX compiler ABI info -- Detecting CXX compiler ABI info - done -- Check for working CXX compiler: /usr/bin/c++ - skipped -- Detecting CXX compile features -- Detecting CXX compile features - done -- Build spdlog: 1.11.0 -- Looking for C++ include pthread.h -- Looking for C++ include pthread.h - found -- Performing Test CMAKE_HAVE_LIBC_PTHREAD -- Performing Test CMAKE_HAVE_LIBC_PTHREAD - Failed -- Looking for pthread_create in pthreads -- Looking for pthread_create in pthreads - not found -- Looking for pthread_create in pthread -- Looking for pthread_create in pthread - found -- Found Threads: TRUE -- Build type: Release -- Configuring done -- Generating done -- Build files have been written to: /workspace/build $ make Scanning dependencies of target spdlog [ 8%] Building CXX object _deps/spdlog-build/CMakeFiles/spdlog.dir/src/spdlog.cpp.o [ 16%] Building CXX object _deps/spdlog-build/CMakeFiles/spdlog.dir/src/stdout_sinks.cpp.o [ 25%] Building CXX object _deps/spdlog-build/CMakeFiles/spdlog.dir/src/color_sinks.cpp.o [ 33%] Building CXX object _deps/spdlog-build/CMakeFiles/spdlog.dir/src/file_sinks.cpp.o [ 41%] Building CXX object _deps/spdlog-build/CMakeFiles/spdlog.dir/src/async.cpp.o [ 50%] Building CXX object _deps/spdlog-build/CMakeFiles/spdlog.dir/src/cfg.cpp.o [ 58%] Building CXX object _deps/spdlog-build/CMakeFiles/spdlog.dir/src/bundled_fmtlib_format.cpp.o [ 66%] Linking CXX static library libspdlog.a [ 66%] Built target spdlog Scanning dependencies of target deviceManager [ 75%] Building CXX object CMakeFiles/deviceManager.dir/deviceManager.cpp.o [ 83%] Linking CXX static library libdeviceManager.a [ 83%] Built target deviceManager Scanning dependencies of target cs [ 91%] Building CXX object CMakeFiles/cs.dir/main.cpp.o [100%] Linking CXX executable cs [100%] Built target cs ```

Output:

$ ./cs
2023-03-25T02:09:21.072+00:00| 1524|    info| cs started
2023-03-25T02:09:21.072+00:00| 1525|    info| from thread: 0
2023-03-25T02:09:21.072+00:00| 1524|    info| 3 threads started
2023-03-25T02:09:21.072+00:00| 1527|    info| from thread: 2
2023-03-25T02:09:21.072+00:00| 1526|    info| from thread: 1
2023-03-25T02:09:21.572+00:00| 1525|    info| from thread: 0
2023-03-25T02:09:21.572+00:00| 1526|    info| from thread: 1
2023-03-25T02:09:21.572+00:00| 1527|    info| from thread: 2
2023-03-25T02:09:22.073+00:00| 1525|    info| from thread: 0
2023-03-25T02:09:22.073+00:00| 1526|    info| from thread: 1
2023-03-25T02:09:22.073+00:00| 1527|    info| from thread: 2
2023-03-25T02:09:22.573+00:00| 1525|    info| from thread: 0
2023-03-25T02:09:22.573+00:00| 1526|    info| from thread: 1
2023-03-25T02:09:22.573+00:00| 1527|    info| from thread: 2
^C

I have encountered a compile error and have fixed two of them (tt4g/the-nitty-gritty@7990b80595da35acd3071a7a40c7540dd62f2a64 , tt4g/the-nitty-gritty@fbebb165ab80c4929babb4a7a0bcd0cecf926ac4). In particular, I could not get deviceManager to build because it did not depend on spdlog (tt4g/the-nitty-gritty@7990b80595da35acd3071a7a40c7540dd62f2a64). This should be a critical bug. If this is the code used in the original project, the library and application may be referencing different spdog binaries. I tried apt-get install libspdlog1=1:1.8.1+ds-2.1 to install spdlog, but this bug was not resolved.

I can only assume it is a machine problem, not spdlog.

[tt4g]

I noticed the following code in the parent CMake directory

https://github.com/alex-lt-kong/the-nitty-gritty/blob/14eca1bc0a4760e5a6ab7798272377a41ccae0c5/mre/CMakeLists.txt

find_library(SPDLOG_LIB spdlog)
if(NOT SPDLOG_LIB)
    message(
        FATAL_ERROR
        "spdlog library not found, install it with 'apt install libspdlog-dev'"
    )
endif()

I installed spdlog with the apt-get install libspdlog-dev=1:1.8.1+ds-2.1 command and the build succeeded even though deviceManager is missing dependency (tt4g/the-nitty-gritty@7990b80595da35acd3071a7a40c7540dd62f2a64).

However, the issue was not reproduced in tt4g/the-nitty-gritty@8a1d966041decf4b8d558631080c51dc6c19d2b4 that made use of libspdlog-dev.

The following CMakeLists.txt shows that deviceManager refers to the libspdlog-dev header installed on the system, and cs refers to another spdlog.

https://github.com/alex-lt-kong/the-nitty-gritty/blob/14eca1bc0a4760e5a6ab7798272377a41ccae0c5/mre/src/camera-server/CMakeLists.txt#L10-L13

I can't investigate this further as it is a problem with your machine, but I suspect that different spdlog binaries are linked.

[alex-lt-kong]

Hi @tt4g before looking into your code, let me clarify the "machine problem" part. It is possible the code has a dependency issue, but this is not the problem of one machine. The program is deployed to multiple machines--currently something like five.

One more thing is, Docker has apt-get install libspdlog1=1:1.8.1+ds-2.1 as well? I suppose apt-get is something Debian/Ubuntu-only, if your host OS is Windows, you can still have apt-get inside a Docker instance?

[tt4g]

The program is deployed to multiple machines--currently something like five.

If you have libspdlog1 installed on all machines, and your CMake project is importing spdlog in a FetchContent kind of way, then the same problem is likely to occur on all machines.

you can still have apt-get inside a Docker instance?

The debian:bullseye-20230320 image has the apt-get command installed so we can use it inside a Docker container.

[alex-lt-kong]

Yes I just tested my code with your CMakeLists.txt, it does appear that issue is gone after I remove

if(NOT TARGET spdlog)
    # Stand-alone build
    find_package(spdlog REQUIRED)
endif()

and revise target_link_libraries() from using target_link_libraries(... spdlog::spdlog) to target_link_libraries(... spdlog fmt).👍👍👍

One more general question though: in the very beginning when I tried to incorporate spdlog into my program, I did struggle to find the "correct" way to add it to my CMakeLists.txt. Is there any official document saying what the best practice should be? For example, how do you know it should be target_link_libraries(... spdlog fmt) instead of something else?

[tt4g]

target_link_libraries() accepts CMake targets and just strings. Passing the CMake target to target_link_libraries() is recommended as it will automatically add the library and its dependencies to your application. However, since the system libraries do not provide CMake targets, target_link_libraries() must accept just strings.

It is difficult to distinguish between CMake targets and just strings in CMakeLists.txt. If find_package(spdlog REQUIRED) is called, spdlog becomes a CMake target, but if not called, spdlog is interpreted as a string (-lspdlog) to be passed to the linker. Having a library with the same name installed on a machine can cause problems like this issue.

The developer has no choice but to be aware of the dependencies between the application and the libraries. You must consider whether you want to use the CMake target system as a way to import the dependent libraries into your project, or simply add the libraries installed on your system to the linked libraries.

The advantage of the CMake target is that it automatically adds library dependencies and necessary compiler options. The advantage of system libraries is that they are tested by the distribution. You can learn about the features of CMake targets in this official document: https://cmake.org/cmake/help/v3.26/manual/cmake-buildsystem.7.html

In any case, I don't think you should have called find_package(spdlog) as you wanted to use the system library. This problem was difficult to solve because it generated an app that links to the CMake target with the same name as the system library defined by find_package(spdlog) and a library that references the system library.

[alex-lt-kong]

I think I tried something like target_link_libraries(... spdlog) heuristically as this is how I can add many other libraries to my project. Unfortunately, this time, it doesn't work--either cmake or g++ complains a lot of errors of whatsoever. So I searched online, rather randomly, and some one recommends this:

if(NOT TARGET spdlog)
    # Stand-alone build
    find_package(spdlog REQUIRED)
endif()

it worked, so I kept it.

I believe that the original issue is that I should add both spdlog and fmt, rather than only spdlog, to my target_link_libraries(). And thus the question, is there any official document saying what the best practice should be? For example, how do you know it should be target_link_libraries(... spdlog fmt) instead of something else?

[tt4g]

As I mentioned in a previous comment, the best practice is to use find_package() if you are using CMake targets. Only the name of the CMake target should be specified in target_link_libraries().

However, since your goal is to use spdlog installed on your system, it is best practice not to use find_package(). When using system libraries, you must check with the library provider to determine what link targets and compile options should be specified. Specify the names of all system libraries that need to be linked to target_link_libraries().

It is the developer's responsibility to consider whether to use the CMake target or the system library.