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

[Bob Murphy]

> On Jul 13, 2020, at 1:42 PM, Jon Siwek <jsiwek at corelight.com> wrote:
> 
> On Fri, Jul 10, 2020 at 11:00 AM Bob Murphy <bob.murphy at corelight.com> wrote:
> 
>> The development I was doing sometimes required me to examine the debug messages from different threads in the chronological order they were generated. But if I understand it correctly, the threading framework’s logging doesn’t maintain that ordering.
> 
> Yeah, or at least the time associated with a Debug message is its
> time-of-processing, not time-of-generation.  Can see how the latter is
> more useful, but want to discuss the proposed solution with a bit more
> detail?  Does it involve a locked mutex around only the underlying
> fprintf() or something more? I imagine it should be "something more"
> if the requirement is to make debug.log a convenient way of
> understanding operation ordering among many threads.
> 
> - Jon

My current implementation does just use a mutex to control access to the output file, and reports the time of generation.

Outside of this email thread, one person has suggested adding something to each debugging log line to identify its source thread. That could potentially be the thread ID, or the thread name, or both.

Another person who runs multiple Zeek instances concurrently also suggested adding the process ID to each log line.

So I was planning to add those to each debug log line before doing a pull request to merge my changes to Zeek master.

- Bob

P.S. If Zeek were to emit a lot of debugging log lines from enough threads very quickly, it’s possible the mutex would add excessive overhead. Boost has a lockfree interthread queue that could be the nucleus of a solution for that, but that would be a lot more complicated than just using a mutex. So I don’t want to look further into that unless and until we know it’s really needed.