hi,
I had a quick look at the code, and the code fragment looks like follows:
if (!exists($corr_list{$key})) {
if (scalar(@{$subst})) {
$action = [];
$action2 = [];
copy_actionlist($ref->{"Action"}, $action);
copy_actionlist($ref->{"Action2"}, $action2);
subst_actionlist($subst, $action, '$');
subst_actionlist($subst, $action2, '$');
} else {
$action = $ref->{"Action"};
$action2 = $ref->{"Action2"};
}
$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"} };
}
$ref2 = $corr_list{$key};
Also, you are calling the dumper function immediately after the last
statement. From this code fragment it is easy to see that
$corr_list{$key} must always exist. Also, the SEC code does not contain
any instructions that would delete all keys from the correlation
operation hash, leaving it an empty hash.
I have also neither seen this behavior myself nor received any similar
bug reports. I can only tell that with some versions of ActiveState Perl
on Windows, SEC tended to crash in the past.
Can you tell more about the platform you are running SEC on? Are you
sure your Perl version is OK? Is your hardware OK?
Last but not least -- from your previous posts I have got an
understanding that you have modified SEC code for your in-house needs.
Are these modifications still in the code, and if so, are you sure they
have not created any side effects?
kind regards,
risto
On 01/18/2010 04:46 PM, antonin mora wrote:
> 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
> Simple-evcorr-users@lists.sourceforge.net
> https://lists.sourceforge.net/lists/listinfo/simple-evcorr-users
>
------------------------------------------------------------------------------
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
Simple-evcorr-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/simple-evcorr-users
