[syslog-ng] Message correlation

[Balazs Scheidler]

hi,

On Thu, 2011-03-03 at 14:01 +0100, Valentijn Sessink wrote:
> > Please find attached my utterly broken postfix-maildelivery trial
> > pattern. For those that are interested: it *does not work*. At all.
> 
> Classic. Forgot the attachment.

I'm not sure in what way it doesn't work, but I've added some debugging
features to correllation with these two patches:

commit 29e889afa7c99c5c64107fcc394505babf8c84bd
Author: Balazs Scheidler <bazsi at balabit.hu>
Date:   Thu Mar 3 17:57:16 2011 +0100

    pdbtool: added internal logging options
    
    This makes it possible to enable debug/verbose messages from pdbtool
    to aid patterndb debug messages.
    
    Signed-off-by: Balazs Scheidler <bazsi at balabit.hu>

commit ef2f6b4791ffb4a93ef019b1b85c2f674c1f660a
Author: Balazs Scheidler <bazsi at balabit.hu>
Date:   Thu Mar 3 17:56:29 2011 +0100

    pdbtool: fixed segfault --debug-pattern in case the pattern doesn't match
    
    Signed-off-by: Balazs Scheidler <bazsi at balabit.hu>

You didn't provide a log sample, so I collected some mail logs 
from our mailserver, but one of the rules didn't match as my log sample
was completely different from yours (probably a postfix version difference?)

Then I've extracted the example log messages in your database, and 
constructed and artificial log file:

2011-03-03T08:05:32.52+01:00 mail postfix/qmgr: 471C2300527: to=<example at mail.example.com>, orig_to=<example at example.com>, relay=example.com[2109:9876:34ab::f1]:25, delay=0.24, delays=0.04/0.01/0.11/0.08, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 6FC19612F6)
2011-03-03T08:05:32.52+01:00 mail postfix/qmgr: 471C2300527: message-id=<201102101555.3RHHEQ8024 at desktop>
2011-03-03T08:05:32.52+01:00 mail postfix/qmgr: 471C2300527: client=example.com[2109:9876:34ab::f1]
2011-03-03T08:05:32.52+01:00 mail postfix/qmgr[3986]: 471C2300527: removed

this messages all match:

# this requires the new debugging patches
$ pdbtool match -p postfix2.pdb -f postfix2.log   -d >/dev/null
Trying to open module; module='syslogformat', filename='/home/bazsi/zwa/install/syslog-ng-ose-3.2/lib/syslog-ng/libsyslogformat.so'
Trying to open module; module='basicfuncs', filename='/home/bazsi/zwa/install/syslog-ng-ose-3.2/lib/syslog-ng/libbasicfuncs.so'
patterndb rule matches; rule_id='39289650-0787-7b4f-a52d-c047d600de3e'
Correllation context lookup failure, starting a new context; rule='39289650-0787-7b4f-a52d-c047d600de3e', context='471C2300527:', context_timeout='0'
patterndb rule matches; rule_id='a249fca8-3916-2444-5238-7495cb64bf76'
Correllation context lookup successful; rule='a249fca8-3916-2444-5238-7495cb64bf76', context='471C2300527:', context_timeout='0', num_messages='1'
patterndb rule matches; rule_id='a649fca8-3916-2444-5238-7495cb64bf76'
Correllation context lookup successful; rule='a649fca8-3916-2444-5238-7495cb64bf76', context='471C2300527:', context_timeout='0', num_messages='2'
patterndb rule matches; rule_id='aaaaaaaa-3946-2444-5238-7495cb64bf76'
Correllation context lookup successful; rule='aaaaaaaa-3946-2444-5238-7495cb64bf76', context='471C2300527:', context_timeout='0', num_messages='3'
Filter node evaluation result; filter_result='match', filter_type='CMP'

The <message> action is triggered, but the values are empty:

$  pdbtool match -p postfix2.pdb -f postfix2.log   -d 2>/dev/null
HOST=mail
MESSAGE=M06 471C2300527:/471C2300527: mail to=<> from=<> connection from=[] msgid=<> orig_to=<>  delay=

But the root cause was that the message indexes didn't match my log sample.

Anyway while doing so, I've discovered that there was another problem with
$(grep), it basically _always_ operated on a single element. I remember that
it actually worked better, but I probably broke it while developing further
features and the unit tests didn't cover all cases properly.

This patch fixes that:

commit a93a4413404d2e3342641cf2be557b1e9b134279
Author: Balazs Scheidler <bazsi at balabit.hu>
Date:   Thu Mar 3 19:19:35 2011 +0100

    templates: fixed @XX style msg_ref parsing
    
    Function invocations (e.g. $(grep)) didn't get the complete
    context as one extremal value for msg_ref (==0) which indicated that
    the user didn't specify an msg_ref was not properly used in the code.
    
    This basically meant that $(grep) only operated on a single element,
    which is not very usable after all.
    
    As it seems the unit test didn't cover all cases properly.
    
    This patch fixes up all cases and adds unit test coverage.
    
    Signed-off-by: Balazs Scheidler <bazsi at balabit.hu>


With this the $(grep) that you embedded in the message started to work fine. 
I've also changed a couple of @xx references in your message template, and I got this:

HOST=mail
MESSAGE=M06 471C2300527:/471C2300527: mail to=<example at mail.example.com> from=<sender at mail.example.com> connection from=example.com[2109:9876:34ab::f1] msgid=<201102101555.3RHHEQ8024 at desktop> orig_to=<example at example.com> 471C2300527:,471C2300527:,471C2300527:,471C2300527:,471C2300527:, delay=0.24, delays=0.04/0.01/0.11/0.08, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 6FC19612F6)

Hopefully, it'll be ok now. Sorry for messing it up this badly :( I probably 
could have spared you a lot of time if I had my testcases done properly.

But anyway, the PE team is now working on properly writing up the correllation
functionality and doing automated tests for them, which are less shabby than my
own, so it'll sure get some drastic improvements in the nearfuture :)

-- 
Bazsi