Hi,

Today I have just found a weird bug in std.logger. Consider:

```d
import std.logger : info;

void main() {
    info(foo());
}

auto foo() {
    info("In foo");
    return "Hello, world.";
}
```

The output is:

```
2023-10-31T20:41:05.274 [info] onlineapp.d:8:foo In foo
2023-10-31T20:41:05.274 [info] onlineapp.d:8:foo In fooHello, world.
```

The second line is obviously wrong, as it repeats the first line as its header. That's why I suspect memory corruption.

Assigning the value to a variable works as expected:

```d
import std.logger : info;

void main() {
    auto s = foo();
    info(s);
}

auto foo() {
    info("In foo");
    return "Hello, world.";
}
```

gets the proper output:

```
2023-10-31T21:09:46.529 [info] onlineapp.d:9:foo In foo
2023-10-31T21:09:46.529 [info] onlineapp.d:5:main Hello, world.
```

I can only imagine that it's related to the logging functions taking lazy arguments, although I cannot see why it would be a problem in a simple case like this.

> I can only imagine that it's related to the logging functions taking lazy arguments, although I cannot see why it would be a problem in a simple case like this.

I've been thinking a bit more about it, and it must be indeed because of the lazy argument.

`foo()` is an argument to `info`, but it also uses the logger. However, because it's a lazy argument, it's not called from `main`, but from `info` itself. I strongly suspect that the problem is that it's not reentrant.

I'm not clear what it's supposed to happen, but assuming this case won't be supported, it should at least be documented. Should I open a bug about it?

On Tuesday, 31 October 2023 at 21:19:34 UTC, Arafel wrote:
> ...
>
> Assigning the value to a variable works as expected:
>
> ```d
> import std.logger : info;
>
> void main() {
>     auto s = foo();
>     info(s);
> }
>
> auto foo() {
>     info("In foo");
>     return "Hello, world.";
> }
> ```
> ...

Unless you do:

    string s;
    info(s=foo());

I think this is a bug, or at least very weird behavior.

Matheus.

On Wednesday, 1 November 2023 at 14:15:55 UTC, matheus wrote:
> On Tuesday, 31 October 2023 at 21:19:34 UTC, Arafel wrote:
>> ...
>>
>> Assigning the value to a variable works as expected:
>>
>> ```d
>> import std.logger : info;
>>
>> void main() {
>>     auto s = foo();
>>     info(s);
>> }
>>
>> auto foo() {
>>     info("In foo");
>>     return "Hello, world.";
>> }
>> ```
>> ...
>
> Unless you do:
>
>     string s;
>     info(s=foo());
>
> I think this is a bug, or at least very weird behavior.
>
> Matheus.
It's really weird: https://run.dlang.io/is/fIBR2n

On Wednesday, 1 November 2023 at 17:26:42 UTC, Christian Köstlin wrote:
> ...
> It's really weird: https://run.dlang.io/is/fIBR2n

Interesting because I wrote a similar test as you did. And that increment (Or lack of) called my attention, If I can I'll try and take a look at that (std.logger) info() Implementation later after work.

Matheus.

On 1/11/23 18:26, Christian Köstlin wrote:
> It's really weird: https://run.dlang.io/is/fIBR2n 

I think I might have found out the issue. It's indeed related to the lazy parameter and reentrance.

The usual logger functions consist of three parts: a header, the message, and the "finalizer". [1]. Internally this is implemented using a string appender [2, 3].

However, this string appender is a member of the class, and this is the source of the bug, because it's shared among all the calls to the logger. It's usually protected by a mutex, so different threads don't mess with each other, but it didn't take reentrancy into account.

And so the call to the logging function within `foo` takes place once the appender is already populated, so this is what happens:

1. Header of first call to `log` (`info`, in this case, but it's irrelevant).
2. Body of first invocation -> Call to `foo()` -> Second call to `log`.
3. The buffer is cleared: The first header is discarded (and previous body, if there were any).
4. The second invocation proceeds normally, and the control returns to the first invocation
5. Now the buffer contains the full content of the previous call, and the return of `foo` is added.

This is exactly what we see. If we do an assignment **before**, then the call is no longer reentrant and everything happens as expected.

So I'd still call it a bug, but at least there seems to be no memory corruption. Also, it doesn't have an easy way to fix it without changing the interface (and potentially affecting already existing custom implementations).

In my view, `writeLogMsg` should create a brand new appender (not a member of the class) that would be passed as a parameter to `beginLogMsg`, `logMsgPart` and `finishLogMsg()`.

Anyway, I think the mystery is more or less solved.

[1]: https://dlang.org/phobos/std_logger_core.html#.Logger
[2]: https://github.com/dlang/phobos/blob/master/std/logger/core.d#L1401
[3]: https://github.com/dlang/phobos/blob/master/std/logger/core.d#L619-L641