stdThreadLocalLog does not print `log` and `trace` logs

[dlangBugzillaToGithub]

ttanjo (@tom-tan) reported this on 2024-03-29T18:56:10Z

Transfered from https://issues.dlang.org/show_bug.cgi?id=24468

CC List

• forestix
• kinke

Description

I reproduce this issue with dmd 2.107.1 on Ubuntu 22.04 and run.dlang.io.
I cannot reproduce this issue with `shaledLog`.

# PoC code
```dlang
import std.logger, std.stdio;

void main()
{
    writeln("==== stdThreadLocalLog ====");
    stdThreadLocalLog.logLevel = LogLevel.all;
    stdThreadLocalLog.log("log");
    stdThreadLocalLog.trace("trace");
    stdThreadLocalLog.info("info");
    stdThreadLocalLog.warning("warning");
    stdThreadLocalLog.error("error");
    stdThreadLocalLog.critical("critical");

    writeln("==== sharedLog ====");
    (cast()sharedLog).logLevel = LogLevel.all;
    (cast()sharedLog).log("log");
    (cast()sharedLog).trace("trace");
    (cast()sharedLog).info("info");
    (cast()sharedLog).warning("warning");
    (cast()sharedLog).error("error");
    (cast()sharedLog).critical("critical");
}

```

# Expected output
Both loggers print `all`, `trace`, `info`, `warning`, `error` and `critical` logs.
```
==== stdThreadLocalLog ====
2024-03-29T18:38:03.881 [all] onlineapp.d:16:main log
2024-03-29T18:38:03.881 [trace] onlineapp.d:17:main trace
2024-03-29T18:38:03.881 [info] onlineapp.d:9:main info
2024-03-29T18:38:03.881 [warning] onlineapp.d:10:main warning
2024-03-29T18:38:03.881 [error] onlineapp.d:11:main error
2024-03-29T18:38:03.881 [critical] onlineapp.d:12:main critical
==== sharedLog ====
2024-03-29T18:38:03.881 [all] onlineapp.d:16:main log
2024-03-29T18:38:03.881 [trace] onlineapp.d:17:main trace
2024-03-29T18:38:03.881 [info] onlineapp.d:18:main info
2024-03-29T18:38:03.881 [warning] onlineapp.d:19:main warning
2024-03-29T18:38:03.882 [error] onlineapp.d:20:main error
2024-03-29T18:38:03.882 [critical] onlineapp.d:21:main critical
```

# Actual behavior
`sharedLog` prints all the logs but `stdThreadLocalLog` lacks `all` and `trace` logs.

```
==== stdThreadLocalLog ====
2024-03-29T18:38:03.881 [info] onlineapp.d:9:main info
2024-03-29T18:38:03.881 [warning] onlineapp.d:10:main warning
2024-03-29T18:38:03.881 [error] onlineapp.d:11:main error
2024-03-29T18:38:03.881 [critical] onlineapp.d:12:main critical
==== sharedLog ====
2024-03-29T18:38:03.881 [all] onlineapp.d:16:main log
2024-03-29T18:38:03.881 [trace] onlineapp.d:17:main trace
2024-03-29T18:38:03.881 [info] onlineapp.d:18:main info
2024-03-29T18:38:03.881 [warning] onlineapp.d:19:main warning
2024-03-29T18:38:03.882 [error] onlineapp.d:20:main error
2024-03-29T18:38:03.882 [critical] onlineapp.d:21:main critical
```

[dlangBugzillaToGithub]

kinke commented on 2024-03-29T22:25:48Z

According to the docs (https://dlang.org/phobos/std_logger_core.html#.stdThreadLocalLog), `stdThreadLocalLog` just forwards to `sharedLog`. The latter has a default LogLevel of info. So in your example, you'd need to set the `sharedLog.logLevel` *before* logging to `stdThreadLocalLog` (which defaults to `LogLevel.all`, forwarding everything to the shared logger).

The key info is in the std.logger package docs (https://dlang.org/phobos/std_logger.html):
> The LogLevel of the stdThreadLocalLog can be used to filter log calls before they reach the sharedLog Logger.

Perhaps this should be duplicated in the documentation for the `stdThreadLocalLog` property.

[dlangBugzillaToGithub]

ttanjo (@tom-tan) commented on 2024-03-30T03:37:33Z

Thank you for the information.
It works when I set `Loglevel.all` to both logger before calling logging methods  as follows.

```dlang
    ...
    (cast()sharedLog).logLevel = LogLevel.all;
    stdThreadLocalLog.logLevel = LogLevel.all;

    writeln("==== stdThreadLocalLog ====");
    stdThreadLocalLog.log("log");
    ...
```

> Perhaps this should be duplicated in the documentation for the `stdThreadLocalLog` property.

I guess the information of default logLevel in each logger should be in the `Thread Local Redirection` section in std.logger because most users read the documents in std.logger first.

Can I close this issue or leave it opened until the document is improved?
If the case of latter, I will send a pull request for it.

[dlangBugzillaToGithub]

forestix commented on 2024-05-28T23:13:54Z

The experience I had today as a newcomer to Phobos logging:

- Read the std.logger docs.
- Create a StdForwardLogger for each of my modules.
  (I want to control each module's log level separately.)
- Discover that trace log messages are silently discarded.
- Set my logger's log level.
- Discover that trace log messages are still silently discarded.
- Read the std.logger docs again.
- Set globalLogLevel.
- Discover that trace log messages are still silently discarded.
- Read the std.logger docs again.
- Set sharedLog.logLevel.
- Discover that the compiler won't let me
  (none of the overloads of `logLevel` are callable using a `shared` mutable object)
- Read the std.logger docs again.
- Notice how much time this basic task is taking, and swear in exasperation.
- Grovel through the dlang forum archive in search of help.
- Find the magic incantation here:
  https://forum.dlang.org/post/mveqddfktkykwvhombsl@forum.dlang.org
  (cast()sharedLog).logLevel = LogLevel.all;
- Try the magic incantation.
- Discover that the compiler won't let me use it in @safe code.

A default log level higher than `trace` is no surprise; that's reasonably common in logging libraries. However, dealing with it in Phobos is surprisingly painful.

In particular, the solution has at least these problems:

- It's nonintuitive.
- It's not clearly documented.
- It's unreasonably awkward for something as common as logging.
- It doesn't work at all in @safe code.

After finally getting to the bottom of it (and nearly giving up on D because this is far from the first Phobos usability problem to bite me) I see that I could work around it in my own programs by using @trusted code. However, I'm writing a library, and I really don't want to require that its users resort to library-specific functions or @trusted shenanigans to control such basic functionality as logging.

It would be nice if this was either fixed by a revised std.logger design, or at least hidden behind a clearly documented standard interface.

[dlangBugzillaToGithub]

forestix commented on 2024-05-29T01:36:00Z

Also, is `(cast()sharedLog).logLevel = LogLevel.all` thread-safe?

If so, how is the user supposed to know that?

If not, where is the thread-safe equivalent?