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

[Bob Murphy]

> On Jul 14, 2020, at 11:35 AM, Jon Siwek <jsiwek at corelight.com> wrote:
> 
> On Tue, Jul 14, 2020 at 8:05 AM Bob Murphy <bob.murphy at corelight.com> wrote:
> 
>> My current implementation does just use a mutex to control access to the output file, and reports the time of generation.
> 
> I was also trying to break down a couple distinct requirements and
> wondered if that actually covers the 2nd:
> 
> (1) Fix the "word salad"
> (2) Ability to examine debug output from multiple threads in chronological order
> 
> Is it fine to just be able to understand the ordering of "when the
> fprintf() happened" or is what's really needed is to understand
> ordering of "when operations associated with debug messages happened"
> ?
> 
> Thread 1:
>  Foo();
>  LockedDebugMsg("I did Foo.");
> 
> Thread 2:
>  Bar();
>  LockedDebugMsg("I did Bar.");
> 
> debug.log
>  [Timestamp 1] I did Foo.
>  [Timestamp 2] I did Bar.
> 
> That debug.log doesn't really tell us whether Foo() happened before
> Bar(), right?
> 
> - Jon

The version I have definitely fixes #1, the word salad. It also fixes #2 in the sense that the output is in the same chronological order the calls to LockedDebugMsg occur.

The code you show should give correct ordering on when Foo() and Bar() finish.

If you also want to know when they start, you could do:
Thread 1:
 LockedDebugMsg(“About to do Foo.");
 Foo();
 LockedDebugMsg("I did Foo.");

Thread 2:
 LockedDebugMsg(“About to do Bar.");
 Bar();
 LockedDebugMsg("I did Bar.”);