Improve an input framework test

A race condition could cause unstable output: if the thread reading the
file is fast, often you see both "pred" functions execute and then both
"line" events execute with both entries already in the table, but if the
thread reading the file is slow, you see pred, event, pred, event, with
only one entry available in the first event.
This commit is contained in:
Jon Siwek 2020-02-07 19:58:35 -08:00
parent a3b1d202a5
commit e50a8848ae
7 changed files with 123 additions and 182 deletions

View file

@ -1,4 +1,8 @@
3.1.0-dev.599 | 2020-02-07 19:58:35 -0800
* Improve an input framework test (Jon Siwek, Corelight)
3.1.0-dev.598 | 2020-02-07 15:06:56 -0800 3.1.0-dev.598 | 2020-02-07 15:06:56 -0800
* Improve stability of a &expire_func btest (Jon Siwek, Corelight) * Improve stability of a &expire_func btest (Jon Siwek, Corelight)

View file

@ -1 +1 @@
3.1.0-dev.598 3.1.0-dev.599

View file

@ -0,0 +1,52 @@
============EVENT============
Description
source, ../input.log
reader, Input::READER_ASCII
mode, Input::REREAD
name, ssh
destination[left = 1], [s=<uninitialized>, ss=TEST]
idx, A::Idx
val, A::Val
want_record, T
Type, Input::EVENT_NEW
Left, [i=1]
Right, [s=<uninitialized>, ss=TEST]
============EVENT============
Description
source, ../input.log
reader, Input::READER_ASCII
mode, Input::REREAD
name, ssh
destination[left = 2], [s=<uninitialized>, ss=<uninitialized>]
idx, A::Idx
val, A::Val
want_record, T
Type, Input::EVENT_NEW
Left, [i=2]
Right, [s=<uninitialized>, ss=<uninitialized>]
============EVENT============
Description
source, ../input.log
reader, Input::READER_ASCII
mode, Input::REREAD
name, ssh
destination[left = 1], [s=TEST, ss=<uninitialized>]
idx, A::Idx
val, A::Val
want_record, T
Type, Input::EVENT_CHANGED
Left, [i=1]
Right, [s=<uninitialized>, ss=TEST]
============EVENT============
Description
source, ../input.log
reader, Input::READER_ASCII
mode, Input::REREAD
name, ssh
destination[left = 2], [s=TEST, ss=TEST]
idx, A::Idx
val, A::Val
want_record, T
Type, Input::EVENT_CHANGED
Left, [i=2]
Right, [s=<uninitialized>, ss=<uninitialized>]

View file

@ -1,155 +0,0 @@
============PREDICATE============
Input::EVENT_NEW
[i=1]
[s=<uninitialized>, ss=TEST]
============PREDICATE============
Input::EVENT_NEW
[i=2]
[s=<uninitialized>, ss=<uninitialized>]
============EVENT============
Description
[source=../input.log, reader=Input::READER_ASCII, mode=Input::REREAD, name=ssh, destination={
[2] = [s=<uninitialized>, ss=<uninitialized>],
[1] = [s=<uninitialized>, ss=TEST]
}, idx=A::Idx, val=A::Val, want_record=T, ev=line
{
print A::outfile, ============EVENT============;
print A::outfile, Description;
print A::outfile, A::description;
print A::outfile, Type;
print A::outfile, A::tpe;
print A::outfile, Left;
print A::outfile, A::left;
print A::outfile, Right;
print A::outfile, A::right;
}, pred=anonymous-function
{
print A::outfile, ============PREDICATE============;
print A::outfile, A::typ;
print A::outfile, A::left;
print A::outfile, A::right;
return (T);
}, error_ev=<uninitialized>, config={
}]
Type
Input::EVENT_NEW
Left
[i=1]
Right
[s=<uninitialized>, ss=TEST]
============EVENT============
Description
[source=../input.log, reader=Input::READER_ASCII, mode=Input::REREAD, name=ssh, destination={
[2] = [s=<uninitialized>, ss=<uninitialized>],
[1] = [s=<uninitialized>, ss=TEST]
}, idx=A::Idx, val=A::Val, want_record=T, ev=line
{
print A::outfile, ============EVENT============;
print A::outfile, Description;
print A::outfile, A::description;
print A::outfile, Type;
print A::outfile, A::tpe;
print A::outfile, Left;
print A::outfile, A::left;
print A::outfile, Right;
print A::outfile, A::right;
}, pred=anonymous-function
{
print A::outfile, ============PREDICATE============;
print A::outfile, A::typ;
print A::outfile, A::left;
print A::outfile, A::right;
return (T);
}, error_ev=<uninitialized>, config={
}]
Type
Input::EVENT_NEW
Left
[i=2]
Right
[s=<uninitialized>, ss=<uninitialized>]
==========SERVERS============
{
[2] = [s=<uninitialized>, ss=<uninitialized>],
[1] = [s=<uninitialized>, ss=TEST]
}
============PREDICATE============
Input::EVENT_CHANGED
[i=1]
[s=TEST, ss=<uninitialized>]
============PREDICATE============
Input::EVENT_CHANGED
[i=2]
[s=TEST, ss=TEST]
============EVENT============
Description
[source=../input.log, reader=Input::READER_ASCII, mode=Input::REREAD, name=ssh, destination={
[2] = [s=TEST, ss=TEST],
[1] = [s=TEST, ss=<uninitialized>]
}, idx=A::Idx, val=A::Val, want_record=T, ev=line
{
print A::outfile, ============EVENT============;
print A::outfile, Description;
print A::outfile, A::description;
print A::outfile, Type;
print A::outfile, A::tpe;
print A::outfile, Left;
print A::outfile, A::left;
print A::outfile, Right;
print A::outfile, A::right;
}, pred=anonymous-function
{
print A::outfile, ============PREDICATE============;
print A::outfile, A::typ;
print A::outfile, A::left;
print A::outfile, A::right;
return (T);
}, error_ev=<uninitialized>, config={
}]
Type
Input::EVENT_CHANGED
Left
[i=1]
Right
[s=<uninitialized>, ss=TEST]
============EVENT============
Description
[source=../input.log, reader=Input::READER_ASCII, mode=Input::REREAD, name=ssh, destination={
[2] = [s=TEST, ss=TEST],
[1] = [s=TEST, ss=<uninitialized>]
}, idx=A::Idx, val=A::Val, want_record=T, ev=line
{
print A::outfile, ============EVENT============;
print A::outfile, Description;
print A::outfile, A::description;
print A::outfile, Type;
print A::outfile, A::tpe;
print A::outfile, Left;
print A::outfile, A::left;
print A::outfile, Right;
print A::outfile, A::right;
}, pred=anonymous-function
{
print A::outfile, ============PREDICATE============;
print A::outfile, A::typ;
print A::outfile, A::left;
print A::outfile, A::right;
return (T);
}, error_ev=<uninitialized>, config={
}]
Type
Input::EVENT_CHANGED
Left
[i=2]
Right
[s=<uninitialized>, ss=<uninitialized>]
==========SERVERS============
{
[2] = [s=TEST, ss=TEST],
[1] = [s=TEST, ss=<uninitialized>]
}
done

View file

@ -0,0 +1,16 @@
============PREDICATE============
Input::EVENT_NEW
[i=1]
[s=<uninitialized>, ss=TEST]
============PREDICATE============
Input::EVENT_NEW
[i=2]
[s=<uninitialized>, ss=<uninitialized>]
============PREDICATE============
Input::EVENT_CHANGED
[i=1]
[s=TEST, ss=<uninitialized>]
============PREDICATE============
Input::EVENT_CHANGED
[i=2]
[s=TEST, ss=TEST]

View file

@ -0,0 +1,11 @@
==========SERVERS============
{
[2] = [s=<uninitialized>, ss=<uninitialized>],
[1] = [s=<uninitialized>, ss=TEST]
}
==========SERVERS============
{
[2] = [s=TEST, ss=TEST],
[1] = [s=TEST, ss=<uninitialized>]
}
done

View file

@ -3,7 +3,9 @@
# @TEST-EXEC: $SCRIPTS/wait-for-file zeek/got1 15|| (btest-bg-wait -k 1 && false) # @TEST-EXEC: $SCRIPTS/wait-for-file zeek/got1 15|| (btest-bg-wait -k 1 && false)
# @TEST-EXEC: mv input2.log input.log # @TEST-EXEC: mv input2.log input.log
# @TEST-EXEC: btest-bg-wait 30 # @TEST-EXEC: btest-bg-wait 30
# @TEST-EXEC: btest-diff out # @TEST-EXEC: btest-diff servers.out
# @TEST-EXEC: btest-diff events.out
# @TEST-EXEC: btest-diff preds.out
@TEST-START-FILE input1.log @TEST-START-FILE input1.log
#separator \x09 #separator \x09
@ -33,54 +35,65 @@ type Val: record {
ss: string; ss: string;
}; };
global servers: table[int] of Val = table(); type servers_type: table[int] of Val;
global servers: servers_type = table();
global outfile: file; global servers_file = open("../servers.out");
global events_file = open("../events.out");
global predicates_file = open("../preds.out");
global try: count; global try: count;
event line(description: Input::TableDescription, tpe: Input::Event, left: Idx, right: Val) event line(description: Input::TableDescription, tpe: Input::Event, left: Idx, right: Val)
{ {
print outfile, "============EVENT============"; print events_file, "============EVENT============";
print outfile, "Description"; print events_file, "Description";
print outfile, description; print events_file, " source", description$source;
print outfile, "Type"; print events_file, " reader", description$reader;
print outfile, tpe; print events_file, " mode", description$mode;
print outfile, "Left"; print events_file, " name", description$name;
print outfile, left; print events_file, fmt(" destination[left = %s]", left$i),
print outfile, "Right"; (description$destination as servers_type)[left$i];
print outfile, right; print events_file, " idx", description$idx;
print events_file, " val", description$val;
print events_file, " want_record", description$want_record;
print events_file, "Type", tpe;
print events_file, "Left", left;
print events_file, "Right", right;
} }
event zeek_init() event zeek_init()
{ {
outfile = open("../out");
try = 0; try = 0;
# first read in the old stuff into the table... # first read in the old stuff into the table...
Input::add_table([$source="../input.log", $mode=Input::REREAD, $name="ssh", $idx=Idx, $val=Val, $destination=servers, $ev=line, Input::add_table([$source="../input.log", $mode=Input::REREAD, $name="ssh",
$pred(typ: Input::Event, left: Idx, right: Val) = { $idx=Idx, $val=Val, $destination=servers, $ev=line,
print outfile, "============PREDICATE============"; $pred(typ: Input::Event, left: Idx, right: Val) = {
print outfile, typ; print predicates_file, "============PREDICATE============";
print outfile, left; print predicates_file, typ;
print outfile, right; print predicates_file, left;
return T; print predicates_file, right;
} return T;
}
]); ]);
} }
event Input::end_of_data(name: string, source: string) event Input::end_of_data(name: string, source: string)
{ {
print outfile, "==========SERVERS============"; print servers_file, "==========SERVERS============";
print outfile, servers; print servers_file, servers;
try = try + 1; try = try + 1;
if ( try == 1 ) if ( try == 1 )
system("touch got1"); system("touch got1");
else if ( try == 2 ) else if ( try == 2 )
{ {
print outfile, "done"; print servers_file, "done";
close(outfile); close(servers_file);
close(events_file);
close(predicates_file);
Input::remove("input"); Input::remove("input");
terminate(); terminate();
} }