This is based on Gilbert's code but I ended up refactoring it quite a
bit. That's why I didn't do a direct merge but started with a new
branch and copied things over to adapt. It looks quite a bit different
now as I tried to generalize things a bit more to also support the
Input Framework.
The larger changes code are:
- Moved all logging code into subdirectory src/logging/. Code
here is in namespace "logging".
- Moved all threading code into subdirectory src/threading/. Code
here is in namespace "threading".
- Introduced a central thread manager that tracks threads and is
in charge of termination and (eventually) statistics.
- Refactored logging independent threading code into base classes
BasicThread and MsgThread. The former encapsulates all the
pthread code with simple start/stop methods and provides a
single Run() method to override.
The latter is derived from BasicThread and adds bi-directional
message passing between main and child threads. The hope is that
the Input Framework can reuse this part quite directly.
- A log writer is now split into a general WriterFrontend
(LogEmissary in Gilbert's code) and a type-specific
WriterBackend. Specific writers are implemented by deriving from
the latter. (The plugin interface is almost unchanged compared
to the 2.0 version.).
Frontend and backend communicate via MsgThread's message
passing.
- MsgThread (and thus WriterBackend) has a Heartbeat() method that
a thread can override to execute code on a regular basis. It's
triggered roughly once a second by the main thread.
- Integration into "the rest of Bro". Threads can send messages to
the reporter and do debugging output; they are hooked into the
I/O loop for sending messages back; and there's a new debugging
stream "threading" that logs, well, threading activity.
This all seems to work for the most part, but it's not done yet.
TODO list:
- Not all tests pass yet. In particular, diffs for the external
tests seem to indicate some memory problem (no crashes, just an
occasional weird character).
- Only tested in --enable-debug mode.
- Only tested on Linux.
- Needs leak check.
- Each log write is currently a single inter-thread message. Bring
Gilbert's bulk writes back.
- Code needs further cleanup.
- Document the class API.
- Document the internal structure of the logging framework.
- Check for robustness: live traffic, aborting, signals, etc.
- Add thread statistics to profile.log (most of the code is there).
- Customize the OS-visible thread names on platforms that support it.
The Logger class is now in charge of reporting all errors, warnings,
informational messages, weirds, and syslogs. All other components
route their messages through the global bro_logger singleton.
The Logger class comes with these reporting methods:
void Message(const char* fmt, ...);
void Warning(const char* fmt, ...);
void Error(const char* fmt, ...);
void FatalError(const char* fmt, ...); // Terminate Bro.
void Weird(const char* name);
[ .. some more Weird() variants ... ]
void Syslog(const char* fmt, ...);
void InternalWarning(const char* fmt, ...);
void InternalError(const char* fmt, ...); // Terminates Bro.
See Logger.h for more information on these.
Generally, the reporting now works as follows:
- All non-fatal message are reported in one of two ways:
(1) At startup (i.e., before we start processing packets),
they are logged to stderr.
(2) During processing, they turn into events:
event log_message%(msg: string, location: string%);
event log_warning%(msg: string, location: string%);
event log_error%(msg: string, location: string%);
The script level can then handle them as desired.
If we don't have an event handler, we fall back to
reporting on stderr.
- All fatal errors are logged to stderr and Bro terminates
immediately.
- Syslog(msg) directly syslogs, but doesn't do anything else.
The three main types of messages can also be generated on the
scripting layer via new Log::* bifs:
Log::error(msg: string);
Log::warning(msg: string);
Log::message(msg: string);
These pass through the bro_logger as well and thus are handled in the
same way. Their output includes location information.
More changes:
- Removed the alarm statement and the alarm_hook event.
- Adapted lots of locations to use the bro_logger, including some
of the messages that were previously either just written to
stdout, or even funneled through the alarm mechanism.
- No distinction anymore between Error() and RunTime(). There's
now only one class of errors; the line was quite blurred already
anyway.
- util.h: all the error()/warn()/message()/run_time()/pinpoint()
functions are gone. Use the bro_logger instead now.
- Script errors are formatted a bit differently due to the
changes. What I've seen so far looks ok to me, but let me know
if there's something odd.
Notes:
- The default handlers for the new log_* events are just dummy
implementations for now since we need to integrate all this into
the new scripts anyway.
- I'm not too happy with the names of the Logger class and its
instance bro_logger. We now have a LogMgr as well, which makes
this all a bit confusing. But I didn't have a good idea for
better names so I stuck with them for now.
Perhaps we should merge Logger and LogMgr?
This pretty much follows the proposal on the projects page.
It includes:
- A new LogMgr, maintaining the set of writers.
- The abstract LogWriter API.
- An initial implementation in the form of LogWriterAscii
producing tab-separated columns.
Note that things are only partially working right now, things are
subject to change, and it's all not much tested at all. That's why I'm
creating separate branch for now.
Example:
bro -B logging test-logging && cat debug.log
1298063168.409852/1298063168.410368 [logging] Created new logging stream 'SSH::LOG_SSH'
1298063168.409852/1298063168.410547 [logging] Created new filter 'default' for stream 'SSH::LOG_SSH'
1298063168.409852/1298063168.410564 [logging] writer : Ascii
1298063168.409852/1298063168.410574 [logging] path : ssh_log_ssh
1298063168.409852/1298063168.410584 [logging] path_func : not set
1298063168.409852/1298063168.410594 [logging] event : not set
1298063168.409852/1298063168.410604 [logging] pred : not set
1298063168.409852/1298063168.410614 [logging] field t: time
1298063168.409852/1298063168.410625 [logging] field id.orig_h: addr
1298063168.409852/1298063168.410635 [logging] field id.orig_p: port
1298063168.409852/1298063168.410645 [logging] field id.resp_h: addr
1298063168.409852/1298063168.410655 [logging] field id.resp_p: port
1298063168.409852/1298063168.410665 [logging] field status: string
1298063168.409852/1298063168.410675 [logging] field country: string
1298063168.409852/1298063168.410817 [logging] Wrote record to filter 'default' on stream 'SSH::LOG_SSH'
1298063168.409852/1298063168.410865 [logging] Wrote record to filter 'default' on stream 'SSH::LOG_SSH'
1298063168.409852/1298063168.410906 [logging] Wrote record to filter 'default' on stream 'SSH::LOG_SSH'
1298063168.409852/1298063168.410945 [logging] Wrote record to filter 'default' on stream 'SSH::LOG_SSH'
1298063168.409852/1298063168.411044 [logging] Wrote record to filter 'default' on stream 'SSH::LOG_SSH
> cat ssh_log_ssh.log
1298063168.40985 1.2.3.4 66770 2.3.4.5 65616 success unknown
1298063168.40985 1.2.3.4 66770 2.3.4.5 65616 failure US
1298063168.40985 1.2.3.4 66770 2.3.4.5 65616 failure UK
1298063168.40985 1.2.3.4 66770 2.3.4.5 65616 success BR
1298063168.40985 1.2.3.4 66770 2.3.4.5 65616 failure MX
