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

[Robin Sommer]

Reading through this thread, I'm wondering if we should focus on
improving identification of log lines in terms of where they come from
and when they were generated, while keeping to go through the existing
mechanism of sending messages back to main process for output (so that
we don't need the mutex). If we sent timestamps & thread IDs along
with the Debug() messages, one could later post-process debug.log to,
get things sorted/split as desired.

This wouldn't support the use case of "millions of lines" very well,
but I'm not convinced that's what we should be designing this for. A
mutex becomes potentially problematic at that volume as well, and it
also seems like a rare use case to begin with. In cases where it's
really needed, a local patch to get logs into files directly (as you
have done already) might just do the trick, no?

Robin

On Tue, Jul 14, 2020 at 14:58 -0700, Bob Murphy wrote:

> 
> > 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.
> 
> 
> 
> _______________________________________________
> Zeek-Dev mailing list
> Zeek-Dev at zeek.org
> http://mailman.icsi.berkeley.edu/mailman/listinfo/zeek-dev


-- 
Robin Sommer * Corelight, Inc. * robin at corelight.com * www.corelight.com