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
