emilk / emilk/loguru

Indentation (i.e. LOG_SCOPE_F) is not thread-safe

Open
#211 3 comments 0 reactions 0 assignees View on GitHub
Dominant language
C++
Stars
1.9k
Forks
280
Avg merge
7m
Merged PRs (30d)
4

Description

First off, I just want to say that the indentation feature is a great idea!

However the current implementation of `LOG_SCOPE_F()` really doesn't support multi-threaded programs, in fact its more of a bug than a feature.

The current indentation level of the log is maintained in a global static variable, [`s_stderr_indentation`](https://github.com/emilk/loguru/blob/89f06b3919413b978a65eac71885f5c0d71b50c2/loguru.cpp#L204) that is shared by all running threads. Calling `LOG_SCOPE_F()` from multiple threads at once essentially wrecks the indentation of the entire log.

## Suggestion:

Mark the indentation variable as `thread_local`, so each running thread maintains its own indentation stack.
*(I realise that some platforms do not support the `thread_local` keyword so that may pose a small challenge.)*

## Example Code

Here's a very simple program you can compile to see what I'm referring too

```c++
#include
#include

#include "loguru.hpp"

using namespace std;

int main(int argc, char *argv[]) {
loguru::init(argc, argv);
LOG_SCOPE_F(INFO, "main()");

this_thread::sleep_for(chrono::milliseconds(500));

thread t1([](){
loguru::set_thread_name("thread1");
LOG_SCOPE_F(INFO, "thread1()");
LOG_F(INFO, "sleeping 1 sec...");
this_thread::sleep_for(chrono::seconds(1));
});

this_thread::sleep_for(chrono::milliseconds(500));

thread t2([](){
loguru::set_thread_name("thread2");
LOG_SCOPE_F(INFO, "thread2()");
LOG_F(INFO, "sleeping 3 sec...");
LOG_F(ERROR, "this is an ERROR");
this_thread::sleep_for(chrono::seconds(3));
});

LOG_F(INFO, "joining...");
t1.join(); // [blocking] t1 should already be finished when we get here
t2.join(); // [blocking] t2 should have ~3 seconds left when we get here
return 0;
}
```

If you don't want to compile it yourself, here's a sample of the output I get when running the executable compiled by the above
code.

## Original Output

**When you pay close attention to the threads, you'll notice that messages print at the wrong indentation level!**

... just imagine what this would look like if your program has 10+ concurrent threads ...

```
date time ( uptime ) [ thread name/id ] file:line v|
2022-04-11 11:08:18.827 ( 0.010s) [main thread ] loguru.cpp:645 INFO| arguments: /real/path/removed/TestLoguru.exe
2022-04-11 11:08:18.845 ( 0.028s) [main thread ] loguru.cpp:648 INFO| Current dir: /real/path/removed
2022-04-11 11:08:18.861 ( 0.043s) [main thread ] loguru.cpp:650 INFO| stderr verbosity: 0
2022-04-11 11:08:18.874 ( 0.056s) [main thread ] loguru.cpp:651 INFO| -----------------------------------
2022-04-11 11:08:18.886 ( 0.068s) [main thread ] main.cpp:10 INFO| { main()
2022-04-11 11:08:19.413 ( 0.595s) [thread1 ] main.cpp:16 INFO| . { thread1()
2022-04-11 11:08:19.425 ( 0.607s) [thread1 ] main.cpp:17 INFO| . . sleeping 1 sec...
2022-04-11 11:08:19.927 ( 1.110s) [thread2 ] main.cpp:25 INFO| . . { thread2()
2022-04-11 11:08:19.927 ( 1.110s) [main thread ] main.cpp:31 INFO| . . . joining...
2022-04-11 11:08:19.943 ( 1.125s) [thread2 ] main.cpp:26 INFO| . . . sleeping 3 sec...
2022-04-11 11:08:19.970 ( 1.152s) [thread2 ] main.cpp:27 ERR| . . . this is an ERROR
2022-04-11 11:08:20.442 ( 1.624s) [thread1 ] main.cpp:16 INFO| . . } 1.029 s: thread1()
2022-04-11 11:08:22.998 ( 4.180s) [thread2 ] main.cpp:25 INFO| . } 3.070 s: thread2()
2022-04-11 11:08:23.012 ( 4.194s) [main thread ] main.cpp:10 INFO| } 4.126 s: main()
2022-04-11 11:08:23.024 ( 4.206s) [main thread ] loguru.cpp:524 INFO| atexit
```

## Output after marking `std_stderr_indentation` as `thread_local`

IMHO this is much more readable than the original especially once you start grep'ing for output on specific threads.

```
date time ( uptime ) [ thread name/id ] file:line v|
2022-04-11 11:09:17.574 ( 0.011s) [main thread ] loguru.cpp:645 INFO| arguments: /real/path/removed/TestLoguru.exe
2022-04-11 11:09:17.591 ( 0.027s) [main thread ] loguru.cpp:648 INFO| Current dir: /real/path/removed
2022-04-11 11:09:17.607 ( 0.043s) [main thread ] loguru.cpp:650 INFO| stderr verbosity: 0
2022-04-11 11:09:17.620 ( 0.056s) [main thread ] loguru.cpp:651 INFO| -----------------------------------
2022-04-11 11:09:17.634 ( 0.070s) [main thread ] main.cpp:10 INFO| { main()
2022-04-11 11:09:18.163 ( 0.599s) [thread1 ] main.cpp:16 INFO| { thread1()
2022-04-11 11:09:18.175 ( 0.611s) [thread1 ] main.cpp:17 INFO| . sleeping 1 sec...
2022-04-11 11:09:18.666 ( 1.102s) [thread2 ] main.cpp:25 INFO| { thread2()
2022-04-11 11:09:18.666 ( 1.102s) [main thread ] main.cpp:31 INFO| . joining...
2022-04-11 11:09:18.678 ( 1.114s) [thread2 ] main.cpp:26 INFO| . sleeping 3 sec...
2022-04-11 11:09:18.705 ( 1.141s) [thread2 ] main.cpp:27 ERR| . this is an ERROR
2022-04-11 11:09:19.197 ( 1.633s) [thread1 ] main.cpp:16 INFO| } 1.034 s: thread1()
2022-04-11 11:09:21.724 ( 4.160s) [thread2 ] main.cpp:25 INFO| } 3.057 s: thread2()
2022-04-11 11:09:21.736 ( 4.172s) [main thread ] main.cpp:10 INFO| } 4.103 s: main()
2022-04-11 11:09:21.749 ( 4.185s) [main thread ] loguru.cpp:524 INFO| atexit
```

Contributor guide

No contributing guide indexed for this repository

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.