Re: removeheaders

Tom Metro wrote:
> Mike Cappella wrote:
>>>> The diff below corrects these issues. I've only tested it with data 
>>>> that matches the first expression.
>>
>> I think the removeheaders optimization you posted can be further 
>> reduced...
>
> Actually the patch I posted was broken, and a reflection of my limited 
> test data. It incorrectly handles the Solaris format because it short 
> circuits on the first match, which is the simpler expression to 
> extract the date-host-service: portion.
Hi Tom,

Heh, that's funny... I had a syntactical typo in mine too!
>
> (BTW, any thoughts on writing unit tests for these scripts?)

I too asked about this some time ago.  The general feedback was 
negative; so I wrote my own basic test data in the amavis and postfix 
scripts.
I would personally like to see  (in no particular order):

1) test logs and golden files
2) per-filter documentation
3) some general project goals
4) some push toward report consistency where appropriate
5) more shared, documented common routines for use by filters
6) some performance push.
7) common Unmatched entries reporting, to assist users in submitting 
reports (rather than tolerating Unmatched lines forever).
8) more integrated debug
9) more detailed change logs
10) push towards more generalized use (vs once/night: I don't think the 
goals of 10 years ago are in alignment with today's more hostile and 
ubiquitous Internet)

I've been contemplating forking a new project if my personal goals are 
not in alignment with the logwatch project's.
>> potentially avoiding calling the RE generator twice for non-matching 
>> lines...
>
> The only good way to answer these questions is to benchamark the 
> variations, which I've done below.
Well, sure, like the old saying, there are lies, damn lies, and there 
are benchmarks!

Seriously, this is good work.  I like the more measured approach.   
Let's be careful to remember that artificial data sets lead to 
artificial conclusions about performance.  For example, my data set and 
measurement shows rh1 (original) and rh4 (consolidate + validation) to 
be slower, with my rh2 falling in between (because of the way the RE 
engine works, longer strings will have more impact).

Jun 24 21:11:27 glacier named[17108]: client 192.168.2.146#3524: view 
internal: update '168.192.in-addr.arpa/IN' denied
       Rate  rh1  rh4  rh2  rh3  rh5
rh1 57571/s   --  -9% -11% -13% -42%
rh4 63171/s  10%   --  -3%  -5% -36%
rh2 64893/s  13%   3%   --  -2% -34%
rh3 66181/s  15%   5%   2%   -- -33%
rh5 98522/s  71%  56%  52%  49%   --

Still, I think it makes sense to focus on large performance areas..  I 
know how to shave off minutes!  [ :-) Sorry Mike, I think 2 minutes is 
too long!  The impact on moderate systems can be noticeable [eg. when 
the large IO xfers cause SA timeouts, etc]


>
> Here are the subroutines and what they represent:
>
> rh1 # original
> rh2 # reduced (your version)
> rh3 # consolidated (3 REs consolidated to 1)
> rh4 # consolidated + validation
> rh5 # optimized for speed (minimal use of RE)
>
> They were ran against the 3 different log line formats, with a sample 
> log line printed before the benchmark results (the left column is 
> ordered from slowest to fastest):
>
> Jun 24 06:58:11 host service[2531]: message
>         Rate  rh2  rh4  rh1  rh3  rh5
> rh2 207039/s   --  -4%  -8%  -8% -27%
> rh4 214592/s   4%   --  -4%  -5% -24%
> rh1 224215/s   8%   4%   --  -1% -21%
> rh3 225734/s   9%   5%   1%   -- -21%
> rh5 284091/s  37%  32%  27%  26%   --
>
> Jun 24 06:48:54 host syslogd 1.4.1#18: restart (remote reception).
>         Rate  rh2  rh4  rh1  rh3  rh5
> rh2 211416/s   --  -3%  -4%  -7% -26%
> rh4 218818/s   4%   --  -1%  -4% -23%
> rh1 221239/s   5%   1%   --  -3% -22%
> rh3 228311/s   8%   4%   3%   -- -20%
> rh5 284900/s  35%  30%  29%  25%   --
>
> Jun 24 06:48:54 host service[2531]: [ID 1234 word.word] Solaris message
>         Rate rh2 rh5 rh3 rh4 rh1
> rh2 165837/s  -- -1% -3% -3% -7%
> rh5 168350/s  2%  -- -2% -2% -6%
> rh3 171233/s  3%  2%  -- -0% -4%
> rh4 171527/s  3%  2%  0%  -- -4%
> rh1 178571/s  8%  6%  4%  4%  --
>
>
> In all cases rh2 (reduced) actually ends up being the slowest.
>
> In the first two (supposedly most common) cases, the original is the 
> second slowest.
>
> The overall speed winner, rh5, which is ~30% faster than the original 
> on the most common log line format, takes a quick-and-dirty approach, 
> and makes minimal use of regular expressions in exchange for 
> performing the least validation of the data.
>
> On the "no colon" data, rh5 also produces different results from the 
> other methods:
>
> Jun 24 06:48:54 host syslogd 1.4.1#18: restart (remote reception).
> rh1:  restart (remote reception).
> rh2:  restart (remote reception).
> rh3:  restart (remote reception).
> rh4:  restart (remote reception).
> rh5:  1.4.1#18: restart (remote reception).
>
> Note how it isn't stripping off the syslog version. I'm not entirely 
> sure which way is actually more correct. It seems arguable to me that 
> the version number is part of the log message and should be included.
>
> The original code appeared to be somewhat sloppy in the validation it 
> was performing. If you consider this RE:
>
> s/^... .. ..:..:.. [^ ]* [^\[:]*(\[\d*\])?: //

I entirely agree - the RE's should be tightened up and validation should 
occur where it matters.
>
> it's saying that the dates can be composed of any characters, as long 
> as they have the right number of characters and the spaces and colons 
> in the right place, and that the host name and service name can be 
> zero length. That doesn't seem right. But maybe things are checked 
> more rigorously upstream.
>
> I'd say if validation was happening upstream, I'd use rh5, otherwise 
> I'd probably pick rh4, which maximizes validation, and I'd add in 
> error handling code to warn about lines that don't match. Though this 
> ends up being about the same performance as the original (+/-2%).
>
> Benchmark script attached. Feel free to try your own variations.
>
> Of course now that we've optimized this, I'd like to voice my 
> agreement with a comment made recently that dates and other "header" 
> information should probably not get stripped off before handing the 
> data to the service filter. As I noted in another message, having a 
> common intermediate log format would permit building an infrastructure 
> for doing common things, like splitting a line into a standard set of 
> components (date, host, service, PID, message), making the job of the 
> service filter just as easy, wile still giving it access to the 
> greater detail if it needs it.

Great!  Let's see what we can come up with.  I'd like to see:

 1) standard date (syslog logs don't include year, vsftpd does, and 
clamd host no time stamps at all.)
 2) hostname
 3) service w/PID (amavis has some non-standard entries, essentially 2 
ids').
 4) log line remainder

MrC

>
>  -Tom