[Zeek-Dev] Proposal: Make Zeek's debug logging thread-safe

[Bob Murphy]

> On Jul 14, 2020, at 1:14 PM, Jon Siwek <jsiwek at corelight.com> wrote:
> 
> On Tue, Jul 14, 2020 at 11:56 AM Bob Murphy <bob.murphy at corelight.com> wrote:
> 
>> The code you show should give correct ordering on when Foo() and Bar() finish.
> 
> Wondering what's meant by "correct ordering" here.  Bar() can finish
> before Foo() and yet debug.log can report "I did Foo" before "I did
> Bar" for whatever thread-scheduling reasons happened to make that the
> case.  Or Foo() and Bar() can execute together in complete concurrency
> and it's just the LockedDebugMsg() picking an arbitrary "winner".
> 
> - Jon

I see your point.

For example:
a. Foo() in thread 1 finishes before Bar() in thread 2 finishes
b. The scheduler deactivates thread 1 for a while between the return from Foo() and the execution of LockedDebugMsg("I did Foo.”)
c. Thread 2 proceeds from the return from Bar() without interruption

Then debug.log would contain the message “I did Bar” before “I did Foo”.

So the ordering in the log file really reflects how the kernel sees the temporal order of mutex locking inside LockedDebugMsg. That’s an inexact approximation of the temporal order of calls to LockedDebugMsg, and that’s an even more inexact approximation of the temporal order of code executed before LockedDebugMsg.

For what I was doing, though, that proved to be good enough. :-)

I’d be very interested in ideas about how to improve that, especially if they’re simple. I can think of a way to improve it, but it would be substantially more complicated than just a mutex.