www.digitalmars.com         C & C++   DMDScript  

digitalmars.D.learn - Weird bug in std.logger? Possible memory corruption

reply Arafel <er.krali gmail.com> writes:
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.
Oct 31 2023
next sibling parent Arafel <er.krali gmail.com> writes:
 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?
Nov 01 2023
prev sibling parent reply matheus <matheus gmail.com> writes:
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.
Nov 01 2023
parent reply Christian =?UTF-8?B?S8O2c3RsaW4=?= <christian.koestlin gmail.com> writes:
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
Nov 01 2023
next sibling parent matheus <matheus gmail.com> writes:
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.
Nov 01 2023
prev sibling parent Arafel <er.krali gmail.com> writes:
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
Nov 01 2023