Per-thread default logger or "current" logger

[falbrechtskirchinger]

I'm looking for a solution to implement a concept I call current logger. It is similar to the default logger but local to each thread.

Basically, I want shared pieces of code to log to a specific logger defined somewhere up the call chain without having to pass logger instances down – or in any other way polluting the interface – using the SPDLOG_<LOG_LEVEL> macros.

In addition, I propose a RAII-style mechanism to set the current logger like so:

{
    // assumes there's a logger foo

    auto log_scope = spdlog::with_logger(foo); // log_scope stores the current default logger
                                               // and sets the new default logger to foo
                                               // (with_default_logger might be a better name)

    // make some calls that log to the default logger, i.e., foo

} // leaving the scope restores the saved default logger

Is there an existing solution I've overlooked?

Otherwise, I suggest introducing a new macro to make the default_logger_ member (effectively) thread_local and adding the proposed RAII-mechanism.

@gabime I'd be happy to submit a PR if you're interested. Some details are to be ironed out but nothing major AFAICT from a cursory look at the code.

Edit: Of course, the initial idea of simply declaring the default_logger_ member thread_local isn't possible. Thus, the change will have to be slightly more invasive than hoped for.

[tt4g]

I don't see any difference between the scope logger API and using std::make_unique() to create logger objects.

[falbrechtskirchinger]

I don't think you understood my main concern. I don't want to have to explicitly pass the logger objects to the functions that may need them. Currently, I'd have to implement my own registry and create custom SPDLOG_<LOG_LEVEL> macros to use that registry. I can do that, but the library almost does what I need it to do anyway, so, I'd much rather address the problem upstream.

[falbrechtskirchinger]

Put differently: spdlog::details::registry::default_logger_ is an application-wide variable, I need a per-thread version of the default logger concept.

[tt4g]

You are right. I did not understand your concept correctly.

[tt4g]

However, spdlog internally identifies loggers by name.
With spdlog's internal registry, this concept is not reentrant.

Wouldn't defining thread_local std::shared_ptr<spdlog::logger> thread_logger and defining an RAII that manipulates thread_logger accomplish your goal?

[falbrechtskirchinger]

I have a working implementation of my proposal (minus the RAII, which is just for convenience anyway). I don't believe it creates any reentrancy issues, but I'll have to think about it more deeply.

And as I've mentioned below, I don't want to redefine all the logging macros.

[gabime]

you could register logger per thread with name=thread id and the use spdlog::get(..) when needed. Not pretty but will work.

When not needed, call spdlog::drop(logger_name)

[gabime]

why macros? no macros meeded

[falbrechtskirchinger]

To log the source information. spdlog doesn't support std::source_location, does it?

[tt4g]

To log the source information. spdlog doesn't support std::source_location, does it?

PR is here #2667

[tt4g]

Logging macros are not complex, so I do not believe it is difficult to define your own macros.

spdlog/include/spdlog/spdlog.h

Lines 304 to 357 in 32bab0e

	#ifndef SPDLOG_NO_SOURCE_LOC
	# define SPDLOG_LOGGER_CALL(logger, level, ...) \
	(logger)->log(spdlog::source_loc{__FILE__, __LINE__, SPDLOG_FUNCTION}, level, __VA_ARGS__)
	#else
	# define SPDLOG_LOGGER_CALL(logger, level, ...) (logger)->log(spdlog::source_loc{}, level, __VA_ARGS__)
	#endif
	#if SPDLOG_ACTIVE_LEVEL <= SPDLOG_LEVEL_TRACE
	# define SPDLOG_LOGGER_TRACE(logger, ...) SPDLOG_LOGGER_CALL(logger, spdlog::level::trace, __VA_ARGS__)
	# define SPDLOG_TRACE(...) SPDLOG_LOGGER_TRACE(spdlog::default_logger_raw(), __VA_ARGS__)
	#else
	# define SPDLOG_LOGGER_TRACE(logger, ...) (void)0
	# define SPDLOG_TRACE(...) (void)0
	#endif
	#if SPDLOG_ACTIVE_LEVEL <= SPDLOG_LEVEL_DEBUG
	# define SPDLOG_LOGGER_DEBUG(logger, ...) SPDLOG_LOGGER_CALL(logger, spdlog::level::debug, __VA_ARGS__)
	# define SPDLOG_DEBUG(...) SPDLOG_LOGGER_DEBUG(spdlog::default_logger_raw(), __VA_ARGS__)
	#else
	# define SPDLOG_LOGGER_DEBUG(logger, ...) (void)0
	# define SPDLOG_DEBUG(...) (void)0
	#endif
	#if SPDLOG_ACTIVE_LEVEL <= SPDLOG_LEVEL_INFO
	# define SPDLOG_LOGGER_INFO(logger, ...) SPDLOG_LOGGER_CALL(logger, spdlog::level::info, __VA_ARGS__)
	# define SPDLOG_INFO(...) SPDLOG_LOGGER_INFO(spdlog::default_logger_raw(), __VA_ARGS__)
	#else
	# define SPDLOG_LOGGER_INFO(logger, ...) (void)0
	# define SPDLOG_INFO(...) (void)0
	#endif
	#if SPDLOG_ACTIVE_LEVEL <= SPDLOG_LEVEL_WARN
	# define SPDLOG_LOGGER_WARN(logger, ...) SPDLOG_LOGGER_CALL(logger, spdlog::level::warn, __VA_ARGS__)
	# define SPDLOG_WARN(...) SPDLOG_LOGGER_WARN(spdlog::default_logger_raw(), __VA_ARGS__)
	#else
	# define SPDLOG_LOGGER_WARN(logger, ...) (void)0
	# define SPDLOG_WARN(...) (void)0
	#endif
	#if SPDLOG_ACTIVE_LEVEL <= SPDLOG_LEVEL_ERROR
	# define SPDLOG_LOGGER_ERROR(logger, ...) SPDLOG_LOGGER_CALL(logger, spdlog::level::err, __VA_ARGS__)
	# define SPDLOG_ERROR(...) SPDLOG_LOGGER_ERROR(spdlog::default_logger_raw(), __VA_ARGS__)
	#else
	# define SPDLOG_LOGGER_ERROR(logger, ...) (void)0
	# define SPDLOG_ERROR(...) (void)0
	#endif
	#if SPDLOG_ACTIVE_LEVEL <= SPDLOG_LEVEL_CRITICAL
	# define SPDLOG_LOGGER_CRITICAL(logger, ...) SPDLOG_LOGGER_CALL(logger, spdlog::level::critical, __VA_ARGS__)
	# define SPDLOG_CRITICAL(...) SPDLOG_LOGGER_CRITICAL(spdlog::default_logger_raw(), __VA_ARGS__)
	#else
	# define SPDLOG_LOGGER_CRITICAL(logger, ...) (void)0
	# define SPDLOG_CRITICAL(...) (void)0
	#endif

[falbrechtskirchinger]

Difficulty isn't the issue, annoyance is. 😉

[gabime]

To log the source information. spdlog doesn't support std::source_location, does it?

No, but it is not related to your question.

You can:

<at start of scope>
auto logger = <create logger with thread_id as the name>
spdlog::register_logger(logger);

...
<use the logger from any thread, using spdlog::get(thread_id)>
..

<at end of scope>
spdlog::drop(logger->name())

Or (preferred), just store logger per thread in the thread local storage.

[falbrechtskirchinger]

I'm trying to remove the need to modify code that is shared between different code bases, where each code base has different requirements with regards to logging and all of them should be satisfied with SPDLOG_DEBUG(...), etc.

I have thought of another solution to achieve the actual goal of this exercise by using a custom formatter and having that pull information from thread local storage, instead of relying on the logger name to tie logged data to its source (meaning caller, not source file and line number).

In any case, I did implement per-thread default loggers. Do I just delete that or are you at all interested?

$ git diff --stat -- CMakeLists.txt include/
 CMakeLists.txt                        |  2 ++
 include/spdlog/details/registry-inl.h | 31 ++++++++++++++++++++++++++++---
 include/spdlog/details/registry.h     |  5 ++++-
 3 files changed, 34 insertions(+), 4 deletions(-)

$ git diff --stat -- tests/
 tests/test_registry.cpp | 98 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 98 insertions(+)

[gabime]

where is the code?

[falbrechtskirchinger]

Here: https://github.com/gabime/spdlog/compare/v1.x...falbrechtskirchinger:per-thread_default_logger?expand=1

As-is the indirection does incur a performance penalty that will have to be remedied. Probably either by inlining get_default_logger_() in registry.h or using a bunch of obnoxious #ifdefs in registry-inl.h.

---

With that being said, I do more and more favor the custom formatter solution that is ultimately more flexible and generic. How would you feel about a format flag for an arbitrary per-thread string (thread label, user string, tag, context, … name TBD, but I like tag). This would to some degree address PR #2149 I remembered reading about a while ago. Not exactly of course, but if one were OK with managing the thread name through a spdlog call, that might be an option for some users.

My proposed RAII mechanism could operate on that per-thread string as well, e.g., auto log_scope = spdlog::with_tag("foo");.

[falbrechtskirchinger]

And here's the code of the pattern_formatter implementation: https://github.com/gabime/spdlog/compare/v1.x...falbrechtskirchinger:spdlog:tag?expand=1

It avoids introducing an ABI-breaking macro (SPDLOG_PER_THREAD_DEFAULT_LOGGER changes the registry object size), and it doesn't introduce performance issues in the default logger code paths, as it's entirely opt-in.

I'm not sure if SPDLOG_NO_TLS should apply to get_tag_(). I'd need to add some documentation and would like to add a unit test using threads before submitting a PR.

I'm awaiting your decision on whether you're interested in either option. Otherwise, I'll just use a custom formatter.

[gabime]

It avoids introducing an ABI-breaking macro (SPDLOG_PER_THREAD_DEFAULT_LOGGER changes the registry object size), and it doesn't introduce performance issues in the default logger code paths, as it's entirely opt-in.

Right, your tag solution is elegant and light . Well done 👍🏼

Few comments:

1. I think the name should be called “context” or similar instead of “tag”.
2. We should consider using a stack of map<string, string> to solve the long standing issues: Mapped Diagnostic Context #532, Adding extra information to logging calls #617, Custom Flag Formatting using Runtime data #2303, Extra attributes for log_msg #2595.
3. There is an issue with async loggers - they execute the flag formatter in a thread pool, so It will not work.

[falbrechtskirchinger]

1. I think the name should be called “context” or similar instead of “tag”.

I've no strong feelings one way or the other. "context" is fine with me.

2. We should consider using a stack of map<string, string> to solve the long standing issues: Mapped Diagnostic Context #532, Adding extra information to logging calls #617, Custom Flag Formatting using Runtime data #2303, Extra attributes for log_msg #2595.

I see I have some reading to do. I'm dealing with another problem right now, but I'll come back to this later today.

3. There is an issue with async loggers - they execute the flag formatter in a thread pool, so It will not work.

There's a flag for the thread ID, right? Does that work around the issue somehow or is that just known to be broken with async logging?

[falbrechtskirchinger]

Alright, I've finished reading through those issues and skimmed the associated code. After thinking about this for the past 5 hours, I'm realizing why no solution has been merged yet.

If I come up with something I consider worthwhile, I'll let you know.

[gabime]

Ok. Thanks @falbrechtskirchinger

[gabime]

There's a flag for the thread ID, right? Does that work around the issue somehow or is that just known to be broken with async logging?

The thread id is copied from the call site and passed along the log message to the queue so its fine.