Sometimes, sec.pl crashes but i don't know why. And if i restart
sec.pl and replay this alert, everything works fine.
I suppose that the problem is in function
"process_singlewiththreshold_rule" so i transformed it to have a lot
of logs.
(I use sec.pl version 2.5.3 and the library dumper to display hashmap)
This problem can happen at any time, before the rule matches,after the
rule matches ... but the logs are always the same, ref2 is empty.
SEC RULE :
type=SingleWithThreshold
continue=TakeNext
ptype=regexp
pattern=^<OscareAlert><source>PHOENIX.BKS1</source><id>(\d{14}-\d{2})</id><message>(?i)(?is).*(VC.*ERROR.*vc.*(\\.*),.*io.*error.*140.*dx.*reason.*link.*state).*(?-i).*</message><node>(?i).*(?-i).*</node>.*
desc=FREQUENCY_MainRuleBKS_FBBA102_027_ERR140-$3
action=send_order contextIdFreq_BKS_FBBA102_027_ERR140-$3 OK;\
create downContextBKS_FBBA102_027_ERR140-$3 -1;
window=3600
thresh=60
FUNCTION :
sub process_singlewiththreshold_rule {
log_msg(LOG_ERR, "#0");
my($ref) = $_[0];
log_msg(LOG_ERR, "Param 0 named ref DUMPER =",Dumper($ref));
my($subst) = $_[1];
log_msg(LOG_ERR, "Param 1 named subst DUMPER =",Dumper($subst));
my($conffile) = $_[2];
log_msg(LOG_ERR, "Param 2 named conffile =",$conffile);
my($context) = $_[3];
log_msg(LOG_ERR, "Param 3 named context DUMPER =",Dumper($context));
my($desc, $key, $time, $action, $action2);
my($ref2, $inside_window, $below_threshold);
$desc = $ref->{"Desc"};
log_msg(LOG_ERR, "desc=",$desc);
log_msg(LOG_ERR, "#1");
if (scalar(@{$subst}))
{
log_msg(LOG_ERR, "#2");
subst_string($subst, $desc, '$');
}
log_msg(LOG_ERR, "#3");
$key = gen_key($conffile, $ref->{"ID"}, $desc);
log_msg(LOG_ERR, "key=",$key);
log_msg(LOG_ERR, "#4");
$time = time();
log_msg(LOG_ERR, "time=",$time);
# if there is no event correlation operation for the key,
# start the new operation
log_msg(LOG_ERR, "#5");
if (!exists($corr_list{$key}))
{
log_msg(LOG_ERR, "corr_list(key) doesn't exist");
}
if (!defined($corr_list{$key}))
{
log_msg(LOG_ERR, "corr_list(key) is not defined");
}
if (!exists($corr_list{$key})) {
log_msg(LOG_ERR, "#6");
if (scalar(@{$subst})) {
log_msg(LOG_ERR, "#7");
$action = [];
$action2 = [];
copy_actionlist($ref->{"Action"}, $action);
log_msg(LOG_ERR, "#8");
copy_actionlist($ref->{"Action2"}, $action2);
log_msg(LOG_ERR, "#9");
subst_actionlist($subst, $action, '$');
log_msg(LOG_ERR, "action=",$action);
log_msg(LOG_ERR, "#10");
subst_actionlist($subst, $action2, '$');
log_msg(LOG_ERR, "action2=",$action2);
log_msg(LOG_ERR, "#11");
} else {
log_msg(LOG_ERR, "#12");
$action = $ref->{"Action"};
log_msg(LOG_ERR, "action=",$action);
log_msg(LOG_ERR, "#13");
$action2 = $ref->{"Action2"};
log_msg(LOG_ERR, "action2=",$action2);
log_msg(LOG_ERR, "#14");
}
log_msg(LOG_ERR, "#15");
$corr_list{$key} = { "Time" => $time,
"Type" => $ref->{"Type"},
"File" => $conffile,
"ID" => $ref->{"ID"},
"Times" => [],
"Window" => $ref->{"Window"},
"Context" => $context,
"Desc" => $desc,
"Action" => $action,
"Action2" => $action2,
"Threshold" => $ref->{"Threshold"} };
log_msg(LOG_ERR, "#16");
}
log_msg(LOG_ERR, "#17");
$ref2 = $corr_list{$key};
log_msg(LOG_ERR, "ref2 DUMPER =",Dumper($ref2));
# inside_window - TRUE if we are still in time window
# below_threshold - TRUE if we were below threshold before this event
log_msg(LOG_ERR, "calculate inside_window with
",$time,$ref2->{"Time"},$ref->{"Window"});
$inside_window = ($time - $ref2->{"Time"} <= $ref->{"Window"});
log_msg(LOG_ERR, "inside_window=",$inside_window);
log_msg(LOG_ERR, "calculate below_threshold with
",scalar(@{$ref2->{"Times"}}),$ref->{"Threshold"});
$below_threshold = (scalar(@{$ref2->{"Times"}}) < $ref->{"Threshold"});
log_msg(LOG_ERR, "below_threshold=",$below_threshold);
log_msg(LOG_ERR, "#18");
if ($inside_window && $below_threshold) {
log_msg(LOG_ERR, "#19");
# if we are inside time window and below threshold, increase
# the counter, and if new value of the counter equals to threshold,
# execute the action list
log_msg(LOG_ERR, "add time into ref2:Times =",$time);
push @{$ref2->{"Times"}}, $time;
log_msg(LOG_ERR, "#20");
if (scalar(@{$ref2->{"Times"}}) == $ref->{"Threshold"})
{
log_msg(LOG_ERR, "#21");
execute_actionlist($ref2->{"Action"}, $desc);
log_msg(LOG_ERR, "#22");
}
log_msg(LOG_ERR, "#23");
}
elsif ($below_threshold) {
log_msg(LOG_ERR, "#24");
# if we are already outside time window but still below
# threshold, slide the window forward
log_msg(LOG_ERR, "add time into ref2:Times =",$time);
push @{$ref2->{"Times"}}, $time;
log_msg(LOG_ERR, "#25");
update_times($ref2, $time);
log_msg(LOG_ERR, "#26");
}
elsif (!$inside_window) {
# if we are both outside time window and above threshold, then
# the 1st action list was executed in the past and this event
# correlation operation has been suppressing post-action events;
# since the operation has expired, execute its 2nd action list
# and start the new operation, because the event we have received
# matches the rule.
log_msg(LOG_ERR, "#27");
execute_actionlist($ref2->{"Action2"}, $desc);
log_msg(LOG_ERR, "#28");
if (scalar(@{$subst})) {
log_msg(LOG_ERR, "#29");
$action = [];
$action2 = [];
copy_actionlist($ref->{"Action"}, $action);
log_msg(LOG_ERR, "#30");
copy_actionlist($ref->{"Action2"}, $action2);
log_msg(LOG_ERR, "#31");
subst_actionlist($subst, $action, '$');
log_msg(LOG_ERR, "#32");
subst_actionlist($subst, $action2, '$');
log_msg(LOG_ERR, "#33");
} else {
log_msg(LOG_ERR, "#34");
$action = $ref->{"Action"};
log_msg(LOG_ERR, "action=",$action);
log_msg(LOG_ERR, "#35");
$action2 = $ref->{"Action2"};
log_msg(LOG_ERR, "action2=",$action2);
log_msg(LOG_ERR, "#36");
}
log_msg(LOG_ERR, "#37");
$corr_list{$key} = { "Time" => $time,
"Type" => $ref->{"Type"},
"File" => $conffile,
"ID" => $ref->{"ID"},
"Times" => [ $time ],
"Window" => $ref->{"Window"},
"Context" => $context,
"Desc" => $desc,
"Action" => $action,
"Action2" => $action2,
"Threshold" => $ref->{"Threshold"} };
log_msg(LOG_ERR, "#38");
if ($ref->{"Threshold"} == 1) {
log_msg(LOG_ERR, "#39");
execute_actionlist($action, $desc);
log_msg(LOG_ERR, "#40");
}
log_msg(LOG_ERR, "#41");
}
log_msg(LOG_ERR, "#42");
}
THIS IS MY LOG FILE :
Mon Jan 18 14:10:30 2010: Writing event '"01263820349968-09 - Mon Jan
18 14:10:30 2010 - LOG RULE FREQUENCY : Message
received[<OscareAlert><source>PHOENIX.BKS1</source><id>01263820349968-09</id><message>2010-01-18
13:55:41 \bkt.$ema *bct.fbba.1 000027 bct.fbba.1
\bkt.$fk42 vc error - vc 0077 5 \bks.$x256.#vc077, io read, error 140
modem err., dx reason 8 clear rcvd, link state 3 up + ready/210.
01000000 vc err 18/01/2010
13:55:41</message><node></node><sop>OSC-BXL-0170</sop><objectCode></objectCode></OscareAlert>]
Identifier[BKS_FBBA102_027_ERR140]' to file output.txt
Mon Jan 18 14:10:30 2010: Filling context
'contextIdFreq_BKS_FBBA102_027_ERR140-\bks.$x256.#vc077' with event
'01263820349968-09'
Mon Jan 18 14:10:30 2010: #0
Mon Jan 18 14:10:30 2010: Param 0 named ref DUMPER = $VAR1 = {
'Action2' => [],
'ContPreEval' => 0,
'PatType' => 1,
'Pattern' =>
qr/(?-xism:^<OscareAlert><source>PHOENIX.BKS1<\/source><id>(\d{14}-\d{2})<\/id><message>(?i)(?is).*(VC.*ERROR.*vc.*(\\.*),.*io.*error.*140.*dx.*reason.*link.*state).*(?-i).*<\/message><node>(?i).*(?-i).*<\/node>.*)/,
'GotoRule' => '3',
'Window' => '3600',
'Desc' => 'FREQUENCY_MainRuleBKS_FBBA102_027_ERR140-$3',
'Threshold' => '60',
'LineNo' => '19',
'MatchCount' => 1,
'ID' => 2,
'Type' => 5,
'Action' => [
23,
'contextIdFreq_BKS_FBBA102_027_ERR140-$3',
'OK',
6,
'downContextBKS_FBBA102_027_ERR140-$3',
'-1',
[]
],
'WhatNext' => 1,
'PatLines' => 1,
'Context' => []
};
Mon Jan 18 14:10:30 2010: Param 1 named subst DUMPER = $VAR1 = [
'<OscareAlert><source>PHOENIX.BKS1</source><id>01263820349968-09</id><message>2010-01-18
13:55:41 \\bkt.$ema *bct.fbba.1 000027 bct.fbba.1
\\bkt.$fk42 vc error - vc 0077 5 \\bks.$x256.#vc077, io read, error
140 modem err., dx reason 8 clear rcvd, link state 3 up + ready/210.
01000000 vc err 18/01/2010
13:55:41</message><node></node><sop>OSC-BXL-0170</sop><objectCode></objectCode></OscareAlert>',
'01263820349968-09',
'vc error - vc 0077 5 \\bks.$x256.#vc077, io read, error 140
modem err., dx reason 8 clear rcvd, link state',
'\\bks.$x256.#vc077'
];
Mon Jan 18 14:10:30 2010: Param 2 named conffile =
/usr/local/OSCARE/CORRELATION_SERVER/confFiles/BKS_FBBA102_027_ERR140.conf
Mon Jan 18 14:10:30 2010: Param 3 named context DUMPER = $VAR1 = [];
Mon Jan 18 14:10:30 2010: desc= FREQUENCY_MainRuleBKS_FBBA102_027_ERR140-$3
Mon Jan 18 14:10:30 2010: #1
Mon Jan 18 14:10:30 2010: #2
Mon Jan 18 14:10:30 2010: #3
Mon Jan 18 14:10:30 2010: key=
/usr/local/OSCARE/CORRELATION_SERVER/confFiles/BKS_FBBA102_027_ERR140.conf
| 2 | FREQUENCY_MainRuleBKS_FBBA102_027_ERR140-\bks.$x256.#vc077
Mon Jan 18 14:10:30 2010: #4
Mon Jan 18 14:10:30 2010: time= 1263820230
Mon Jan 18 14:10:30 2010: #5
Mon Jan 18 14:10:30 2010: #17
Mon Jan 18 14:10:30 2010: ref2 DUMPER = $VAR1 = {};
Mon Jan 18 14:10:30 2010: calculate inside_window with 1263820230 3600
Mon Jan 18 14:10:30 2010: inside_window=
I think the problem is when we get ref2, there is nothing inside and i
don't know how it is possible. Did you already have this problem ? Do
you have any clue to resolve it ?
THE "SAME" ALERT WITH "GOOD" LOG :
Mon Jan 18 13:33:10 2010: Filling context
'contextIdFreq_BKS_FBBA102_027_ERR140-\bkt.$x124.#vc021' with event
'01263818242906-44'
Mon Jan 18 13:33:10 2010: #0
Mon Jan 18 13:33:10 2010: Param 0 named ref DUMPER = $VAR1 = {
'Action2' => [],
'ContPreEval' => 0,
'PatType' => 1,
'Pattern' =>
qr/(?-xism:^<OscareAlert><source>PHOENIX.BKS1<\/source><id>(\d{14}-\d{2})<\/id><message>(?i)(?is).*(VC.*ERROR.*vc.*(\\.*),.*io.*error.*140.*dx.*reason.*link.*state).*(?-i).*<\/message><node>(?i).*(?-i).*<\/node>.*)/,
'GotoRule' => '3',
'Window' => '3600',
'Desc' => 'FREQUENCY_MainRuleBKS_FBBA102_027_ERR140-$3',
'Threshold' => '60',
'LineNo' => '19',
'MatchCount' => 3,
'ID' => 2,
'Type' => 5,
'Action' => [
23,
'contextIdFreq_BKS_FBBA102_027_ERR140-$3',
'OK',
6,
'downContextBKS_FBBA102_027_ERR140-$3',
0,
[]
],
'WhatNext' => 1,
'PatLines' => 1,
'Context' => []
};
Mon Jan 18 13:33:10 2010: Param 1 named subst DUMPER = $VAR1 = [
'<OscareAlert><source>PHOENIX.BKS1</source><id>01263818242906-44</id><message>2010-01-18
11:41:41 \\bkt.$ema *bct.fbba.1 000027 bct.fbba.1
\\bkt.$fk51 vc error - vc 0021 5 \\bkt.$x124.#vc021, io read, error
140 modem err., dx reason 8 clear rcvd, link state 3 up + ready/000.
01000000 vc err 18/01/2010
11:41:41</message><node></node><sop>OSC-BXL-0170</sop><objectCode></objectCode></OscareAlert>',
'01263818242906-44',
'vc error - vc 0021 5 \\bkt.$x124.#vc021, io read, error 140
modem err., dx reason 8 clear rcvd, link state',
'\\bkt.$x124.#vc021'
];
Mon Jan 18 13:33:10 2010: Param 2 named conffile =
/usr/local/OSCARE/CORRELATION_SERVER/confFiles/BKS_FBBA102_027_ERR140.conf
Mon Jan 18 13:33:10 2010: Param 3 named context DUMPER = $VAR1 = [];
Mon Jan 18 13:33:10 2010: desc= FREQUENCY_MainRuleBKS_FBBA102_027_ERR140-$3
Mon Jan 18 13:33:10 2010: #1
Mon Jan 18 13:33:10 2010: #2
Mon Jan 18 13:33:10 2010: #3
Mon Jan 18 13:33:10 2010: key=
/usr/local/OSCARE/CORRELATION_SERVER/confFiles/BKS_FBBA102_027_ERR140.conf
| 2 | FREQUENCY_MainRuleBKS_FBBA102_027_ERR140-\bkt.$x124.#vc021
Mon Jan 18 13:33:10 2010: #4
Mon Jan 18 13:33:10 2010: time= 1263817990
Mon Jan 18 13:33:10 2010: #5
Mon Jan 18 13:33:10 2010: #17
Mon Jan 18 13:33:10 2010: ref2 DUMPER = $VAR1 = {
'Action2' => [],
'Desc' =>
'FREQUENCY_MainRuleBKS_FBBA102_027_ERR140-\\bkt.$x124.#vc021',
'Window' => '3600',
'Threshold' => '60',
'Time' => 1263817978,
'ID' => 2,
'File' =>
'/usr/local/OSCARE/CORRELATION_SERVER/confFiles/BKS_FBBA102_027_ERR140.conf',
'Times' => [
1263817978
],
'Type' => 5,
'Action' => [
23,
'contextIdFreq_BKS_FBBA102_027_ERR140-\\bkt.$x124.#vc021',
'OK',
6,
'downContextBKS_FBBA102_027_ERR140-\\bkt.$x124.#vc021',
0,
[]
],
'Context' => []
};
Mon Jan 18 13:33:10 2010: calculate inside_window with 1263817990
1263817978 3600
Mon Jan 18 13:33:10 2010: inside_window= 1
Mon Jan 18 13:33:10 2010: calculate below_threshold with 1 60
Mon Jan 18 13:33:10 2010: below_threshold= 1
Mon Jan 18 13:33:10 2010: #18
Mon Jan 18 13:33:10 2010: #19
Mon Jan 18 13:33:10 2010: add time into ref2:Times = 1263817990
Mon Jan 18 13:33:10 2010: #20
Mon Jan 18 13:33:10 2010: #23
Mon Jan 18 13:33:10 2010: #42
Best regards,
Antonin.
------------------------------------------------------------------------------
Throughout its 18-year history, RSA Conference consistently attracts the
world's best and brightest in the field, creating opportunities for Conference
attendees to learn about information security's most important issues through
interactions with peers, luminaries and emerging and established companies.
http://p.sf.net/sfu/rsaconf-dev2dev
_______________________________________________
Simple-evcorr-users mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/simple-evcorr-users
