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

[skaravos]

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 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

#include <chrono>
#include <thread>

#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

[emilk]

First of all, there is a point of confusion here that need clearing up: [s_stderr_indentation](https://github.com/emilk/loguru/blob/89f06b3919413b978a65eac71885f5c0d71b50c2/loguru.cpp#L204) is thread-safe, because it uses atomics. It is thus intentionally, and safely, shared between threads.

Whether or not this is good behavior depends on context.

When I wrote it I had this case in mind:

void do_jobs() {
  LOG_SCOPE_F(INFO, "doing_stuff");

  thread t1([](){
    // logs a few lines (e.g. warnings) but doesn't create scopes
  });

  thread t2([](){
    // logs a few lines (e.g. warnings) but doesn't create scopes
  });

  t1.join();
  t2.join();
}

in this example the current behavior is better, as the log lines in the child threads are correctly indented.

So just switching to thread local indentation level will make some use cases worse.

We could consider having a compile-time switch for it.

Another solution is to have a mechanism to copy (or not) the current indentation level to a child thread. Perhaps even trace the parent thread with something like:

auto parent = loguru::thread_info();
thread t1([=](){
  loguru::set_parent_thread(parent); // copy indentation level, and print parent thread name in error context
});

[skaravos]

Agreed that it's 100% thread-safe from a data-access point of view, certainly nothing is corrupted and no messages are lost. Sorry for the confusion there.

I was referring to a stretched definition of "thread-safe" whereby the current implementation causes indentation behavior on any given run be non-deterministic.
Specifically: the same logged message will be logged with a different indentation level depending on which threads finish first.

Seeing your original intent, I now understand why you chose to use a regular static variable.
However, I really think LOG_SCOPE_F has the potential to be a powerful feature that is limited by essentially restricting its use to a single parent thread.

Both of your suggestions would solve the problem, although the second solution is more flexible. Passing some informational context from the parent thread could allow threads to inherit more than just indentation information.

In fact, that solution would result in the exact behavior I had originally expected after reading the docs.

Just as an example: This is what I thought would happen when I originally ran my test program.
(The child threads maintain their own depth counter that was initialized based on parent depth)

...[main   ] loguru.cpp:645   INFO| arguments: /real/path/removed/TestLoguru.exe
...[main   ] loguru.cpp:648   INFO| Current dir: /real/path/removed
...[main   ] loguru.cpp:650   INFO| stderr verbosity: 0
...[main   ] loguru.cpp:651   INFO| -----------------------------------
...[main   ]   main.cpp:10    INFO| { main()
...[thread1]   main.cpp:16    INFO| .   { thread1()
...[thread1]   main.cpp:17    INFO| .   .   sleeping 1 sec...
...[thread2]   main.cpp:25    INFO| .   { thread2()
...[main   ]   main.cpp:31    INFO| .   joining...
...[thread2]   main.cpp:26    INFO| .   .   sleeping 3 sec...
...[thread2]   main.cpp:27     ERR| .   .   this is an ERROR
...[thread1]   main.cpp:16    INFO| .   } 1.029 s: thread1()
...[thread2]   main.cpp:25    INFO| .   } 3.070 s: thread2()
...[main   ]   main.cpp:10    INFO| } 4.126 s: main()
...[main   ] loguru.cpp:524   INFO| atexit

With that said... the compile-time switch is a lot easier to implement and would avoid any runtime overhead, so maybe that's the better solution.

P.S. somewhat related: it would be nice to have a way to disable indentation or change the width without also disabling the preamble (maybe a LOGURU_SCOPE_INDENTATION_WIDTH definition that defaults to 4?)

[plq]

Sorry for resurrecting an old thread but it could be useful to add LOG_GSCOPE_F (for global scope), LOG_TSCOPE_F (for thread scope), both of which would in turn call the LOG_CSCOPE_F (for custom scope) that takes an additional scope object as an argument. Adding a compilation flag would be cumbersome and wouldn't really solve the problem.

At this point maybe LOG_SCOPE_F (which became just an alias to LOG_GSCOPE_F) would have to be deprecated to avoid confusion.