mirror of
https://github.com/zeek/zeek.git
synced 2025-10-13 03:58:20 +00:00
Merge remote-tracking branch 'origin/topic/awelzel/log-write-delay-3'
* origin/topic/awelzel/log-write-delay-3: logging: ref() to record_ref() renaming logging: Fix typos from review logging/Manager: Make LogDelayExpiredTimer an implementation detail logging/WriteToFilters: Use range-based for loop testing/btest: Log::delay() from JavaScript NEWS: Entry for delayed log writes Bump doc submodule to branch logging: Do not keep delay state persistent logging: delay documentation polishing logging: Better error messages for invalid Log::delay() calls logging/Manager: Implement DelayTokenType as an actual opaque logging: Implement get_delay_queue_size() logging: Introduce Log::delay() and Log::delay_finish() logging/Manager: zeek::detail'ify logging/Manager: Split Write() Timer: Add LOG_DELAY_EXPIRE timer type Ascii: Remove extra include
This commit is contained in:
Arne Welzel
commit
28eef9e4b2
124 changed files with 3962 additions and 103 deletions
122
testing/btest/scripts/base/frameworks/logging/delay/basic.zeek
Normal file
122
testing/btest/scripts/base/frameworks/logging/delay/basic.zeek
Normal file
|
|
@ -0,0 +1,122 @@
|
|||
# @TEST-DOC: Basic tests.
|
||||
|
||||
# @TEST-EXEC: zeek -B logging,tm -b -r $TRACES/http/get.trace test.zeek %INPUT
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff .stdout
|
||||
# @TEST-EXEC: btest-diff .stderr
|
||||
# @TEST-EXEC: touch test.log && zeek-cut -m -F'|' < test.log > test.cut
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test.cut
|
||||
|
||||
|
||||
@TEST-START-FILE test.zeek
|
||||
# Used by all tests below.
|
||||
|
||||
# Debug printing
|
||||
global packet_count = 0;
|
||||
event new_packet(c: connection, p: pkt_hdr)
|
||||
{
|
||||
++packet_count;
|
||||
print network_time(), "new_packet", packet_count;
|
||||
}
|
||||
|
||||
event Pcap::file_done(p: string)
|
||||
{
|
||||
print network_time(), "Pcap::file_done";
|
||||
}
|
||||
|
||||
redef enum Log::ID += {
|
||||
LOG
|
||||
};
|
||||
|
||||
type Info: record {
|
||||
ts: time &log;
|
||||
write_ts: time &log &optional;
|
||||
uid: string &log;
|
||||
msg: string &log;
|
||||
};
|
||||
|
||||
hook log_policy(rec: Info, id: Log::ID, filter: Log::Filter)
|
||||
{
|
||||
print network_time(), "log_policy", rec$uid;
|
||||
rec$write_ts = network_time();
|
||||
}
|
||||
|
||||
event zeek_init()
|
||||
{
|
||||
Log::create_stream(LOG, [$columns=Info, $path="test", $policy=log_policy]);
|
||||
}
|
||||
|
||||
event new_connection(c: connection)
|
||||
{
|
||||
print network_time(), "new_connection", c$uid;
|
||||
local info = Info($ts=network_time(), $uid=c$uid, $msg="inital-value");
|
||||
Log::write(LOG, info);
|
||||
}
|
||||
@TEST-END-FILE test.zeek
|
||||
|
||||
|
||||
# Delay and immediately release.
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
print network_time(), "log_stream_policy", id, rec$uid;
|
||||
|
||||
local token = Log::delay(id, rec);
|
||||
Log::delay_finish(id, rec, token);
|
||||
}
|
||||
|
||||
@TEST-START-NEXT
|
||||
# Delay and immediately release, twice.
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
print network_time(), "log_stream_policy", id, rec$uid;
|
||||
|
||||
local token1 = Log::delay(id, rec);
|
||||
Log::delay_finish(id, rec, token1);
|
||||
|
||||
local token2 = Log::delay(id, rec);
|
||||
Log::delay_finish(id, rec, token2);
|
||||
}
|
||||
|
||||
@TEST-START-NEXT
|
||||
# Delay once, never release.
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
print network_time(), "log_stream_policy", id, rec$uid;
|
||||
|
||||
Log::delay(id, rec);
|
||||
}
|
||||
|
||||
@TEST-START-NEXT
|
||||
# Delay twice, never release.
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
print network_time(), "log_stream_policy", id, rec$uid;
|
||||
|
||||
Log::delay(id, rec);
|
||||
Log::delay(id, rec);
|
||||
}
|
||||
|
||||
@TEST-START-NEXT
|
||||
# Delay twice, never release, print the token value and its JSON representation.
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
print network_time(), "log_stream_policy", id, rec$uid;
|
||||
|
||||
local token = Log::delay(id, rec);
|
||||
print "token", token;
|
||||
print "to_json(token)", to_json(token);
|
||||
}
|
||||
|
|
@ -0,0 +1,80 @@
|
|||
# @TEST-DOC: Check usage delay in when statements.
|
||||
|
||||
# @TEST-EXEC: zeek -B tm,logging -b -r $TRACES/http/get.trace test.zeek %INPUT
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff .stdout
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stderr
|
||||
|
||||
# @TEST-EXEC: zeek-cut -m -F'|' < test.log > test.cut
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test.cut
|
||||
|
||||
@TEST-START-FILE test.zeek
|
||||
# Debug printing
|
||||
global packet_count = 0;
|
||||
event new_packet(c: connection, p: pkt_hdr)
|
||||
{
|
||||
++packet_count;
|
||||
print network_time(), "new_packet", packet_count;
|
||||
}
|
||||
|
||||
event Pcap::file_done(p: string)
|
||||
{
|
||||
print network_time(), "Pcap::file_done";
|
||||
}
|
||||
|
||||
redef enum Log::ID += {
|
||||
LOG
|
||||
};
|
||||
|
||||
type Info: record {
|
||||
ts: time &log;
|
||||
write_ts: time &log &optional;
|
||||
uid: string &log;
|
||||
msg: string &log;
|
||||
};
|
||||
|
||||
hook log_policy(rec: Info, id: Log::ID, filter: Log::Filter)
|
||||
{
|
||||
print network_time(), "log_policy", rec$uid;
|
||||
rec$write_ts = network_time();
|
||||
}
|
||||
|
||||
event zeek_init()
|
||||
{
|
||||
Log::create_stream(LOG, [$columns=Info, $path="test", $policy=log_policy]);
|
||||
}
|
||||
@TEST-END-FILE test.zeek
|
||||
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool {
|
||||
local delayed_for = network_time() - now;
|
||||
rec2$msg = fmt("%s delayed %s", rec2$msg, delayed_for);
|
||||
print network_time(), "post_delay_cb", rec2;
|
||||
return T;
|
||||
});
|
||||
}
|
||||
|
||||
event new_connection(c: connection)
|
||||
{
|
||||
print network_time(), "new_connection", c$uid;
|
||||
|
||||
# Using an anonymous record type with field reordering.
|
||||
#
|
||||
# This is quirky: Because internally this record is coerced
|
||||
# very early on, the hooks and delay pipeline work with a different
|
||||
# record val ptr. So an update of this record is not visible!
|
||||
local info = [$msg="initial-value", $ts=network_time(), $uid=c$uid];
|
||||
|
||||
Log::write(LOG, info);
|
||||
|
||||
# Not visible after delay due to record coercion.
|
||||
print network_time(), "Updating info$msg after write!";
|
||||
info$msg = "after-write";
|
||||
}
|
||||
|
|
@ -0,0 +1,118 @@
|
|||
# @TEST-DOC: Calling Log::delay() during the post delay callback()
|
||||
#
|
||||
# @TEST-EXEC: zeek -B logging,tm -b -r $TRACES/http/get.trace test.zeek %INPUT
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff .stdout
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stderr
|
||||
|
||||
# @TEST-EXEC: touch test.log && zeek-cut -m -F'|' < test.log > test.cut
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test.cut
|
||||
|
||||
redef Log::default_max_delay_interval = 50msec;
|
||||
|
||||
@TEST-START-FILE test.zeek
|
||||
|
||||
global packet_count = 0;
|
||||
event new_packet(c: connection, p: pkt_hdr)
|
||||
{
|
||||
++packet_count;
|
||||
print network_time(), "new_packet", packet_count;
|
||||
}
|
||||
|
||||
event Pcap::file_done(p: string)
|
||||
{
|
||||
print network_time(), "Pcap::file_done";
|
||||
}
|
||||
|
||||
redef enum Log::ID += {
|
||||
LOG
|
||||
};
|
||||
|
||||
type Info: record {
|
||||
ts: time &log;
|
||||
write_ts: time &log &optional;
|
||||
uid: string &log;
|
||||
msg: string &log;
|
||||
};
|
||||
|
||||
hook log_policy(rec: Info, id: Log::ID, filter: Log::Filter)
|
||||
{
|
||||
print network_time(), "log_policy", rec$uid;
|
||||
rec$write_ts = network_time();
|
||||
}
|
||||
|
||||
event zeek_init()
|
||||
{
|
||||
Log::create_stream(LOG, [$columns=Info, $path="test", $policy=log_policy]);
|
||||
}
|
||||
|
||||
event new_connection(c: connection)
|
||||
{
|
||||
print network_time(), "new_connection", c$uid;
|
||||
local info = Info($ts=network_time(), $uid=c$uid, $msg="inital-value");
|
||||
Log::write(LOG, info);
|
||||
}
|
||||
@TEST-END-FILE test.zeek
|
||||
|
||||
# Delay the given record twice using a nested lambda.
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool {
|
||||
local delayed_for = network_time() - now;
|
||||
print network_time(), "post_delay_cb - 1", rec2, delayed_for;
|
||||
|
||||
Log::delay(LOG, rec2, function[now](rec3: Info, id3: Log::ID): bool {
|
||||
local delayed_for2 = network_time() - now;
|
||||
rec3$msg = fmt("%s delayed %s", rec3$msg, delayed_for2);
|
||||
print network_time(), "post_delay_cb - 2", rec3, delayed_for2;
|
||||
return T;
|
||||
});
|
||||
|
||||
return T;
|
||||
});
|
||||
|
||||
when [rec] ( T == F )
|
||||
{
|
||||
}
|
||||
timeout 10msec
|
||||
{
|
||||
print network_time(), "when timeout", rec;
|
||||
}
|
||||
}
|
||||
|
||||
@TEST-START-NEXT
|
||||
# Delay the given record twice using a nested lambda, but also immediate release.
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
local token1 = Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool {
|
||||
local delayed_for = network_time() - now;
|
||||
print network_time(), "post_delay_cb - 1, delaying again", rec2, delayed_for;
|
||||
|
||||
local token2 = Log::delay(LOG, rec2, function[now](rec3: Info, id3: Log::ID): bool {
|
||||
local delayed_for2 = network_time() - now;
|
||||
rec3$msg = fmt("%s delayed %s", rec3$msg, delayed_for2);
|
||||
print network_time(), "post_delay_cb - 2", rec3, delayed_for2;
|
||||
return T;
|
||||
});
|
||||
|
||||
print network_time(), "post_delay_cb - 1, delay_finish", rec2, delayed_for;
|
||||
Log::delay_finish(LOG, rec2, token2);
|
||||
|
||||
return T;
|
||||
});
|
||||
|
||||
Log::delay_finish(LOG, rec, token1);
|
||||
}
|
||||
|
|
@ -0,0 +1,223 @@
|
|||
# @TEST-DOC: Test the post delay callback and timing behavior.
|
||||
#
|
||||
# During new_connection() a Log::write() happens. Each packet is printed
|
||||
# to observe timing behavior.
|
||||
#
|
||||
# @TEST-EXEC: zeek -B logging,tm -b -r $TRACES/http/get.trace test.zeek %INPUT
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff .stdout
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stderr
|
||||
|
||||
# @TEST-EXEC: touch test.log && zeek-cut -m -F'|' < test.log > test.cut
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test.cut
|
||||
|
||||
@TEST-START-FILE test.zeek
|
||||
|
||||
global packet_count = 0;
|
||||
event new_packet(c: connection, p: pkt_hdr)
|
||||
{
|
||||
++packet_count;
|
||||
print network_time(), "new_packet", packet_count;
|
||||
}
|
||||
|
||||
event Pcap::file_done(p: string)
|
||||
{
|
||||
print network_time(), "Pcap::file_done";
|
||||
}
|
||||
|
||||
redef enum Log::ID += {
|
||||
LOG
|
||||
};
|
||||
|
||||
type Info: record {
|
||||
ts: time &log;
|
||||
write_ts: time &log &optional;
|
||||
uid: string &log;
|
||||
msg: string &log;
|
||||
};
|
||||
|
||||
hook log_policy(rec: Info, id: Log::ID, filter: Log::Filter)
|
||||
{
|
||||
print network_time(), "log_policy", rec$uid;
|
||||
rec$write_ts = network_time();
|
||||
}
|
||||
|
||||
event zeek_init()
|
||||
{
|
||||
Log::create_stream(LOG, [$columns=Info, $path="test", $policy=log_policy]);
|
||||
}
|
||||
|
||||
event new_connection(c: connection)
|
||||
{
|
||||
print network_time(), "new_connection", c$uid;
|
||||
local info = Info($ts=network_time(), $uid=c$uid, $msg="inital-value");
|
||||
Log::write(LOG, info);
|
||||
}
|
||||
@TEST-END-FILE test.zeek
|
||||
|
||||
# Basic delay() test, no delay_finish()
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool {
|
||||
local delayed_for = network_time() - now;
|
||||
rec2$msg = fmt("%s delayed %s", rec2$msg, delayed_for);
|
||||
print network_time(), "post_delay_cb", rec2, delayed_for;
|
||||
return T;
|
||||
});
|
||||
|
||||
when [rec] ( T == F )
|
||||
{
|
||||
}
|
||||
timeout 10msec
|
||||
{
|
||||
print network_time(), "when timeout", rec;
|
||||
}
|
||||
}
|
||||
|
||||
# @TEST-START-NEXT
|
||||
# Basic delay() test with delay_finish(), expect callback to be invoked
|
||||
# right at Log::delay_finish()
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
local token = Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool {
|
||||
local delayed_for = network_time() - now;
|
||||
rec2$msg = fmt("%s delayed %s", rec2$msg, delayed_for);
|
||||
print network_time(), "post_delay_cb", rec2, delayed_for;
|
||||
return T;
|
||||
});
|
||||
|
||||
when [id, rec, token] ( T == F )
|
||||
{
|
||||
}
|
||||
timeout 10msec
|
||||
{
|
||||
print network_time(), "when timeout", rec;
|
||||
Log::delay_finish(id, rec, token);
|
||||
}
|
||||
}
|
||||
|
||||
# @TEST-START-NEXT
|
||||
# Basic delay() test with two callbacks but just one Log::delay_finish() call.
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
local token1 = Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool {
|
||||
local delayed_for = network_time() - now;
|
||||
rec2$msg = fmt("%s delayed %s", rec2$msg, delayed_for);
|
||||
print network_time(), "post_delay_cb - 1", rec2, delayed_for;
|
||||
return T;
|
||||
});
|
||||
|
||||
local token2 = Log::delay(LOG, rec, function(rec2: Info, id2: Log::ID): bool {
|
||||
print network_time(), "post_delay_cb - 2", rec2;
|
||||
return T;
|
||||
});
|
||||
|
||||
when [id, rec, token1] ( T == F )
|
||||
{
|
||||
}
|
||||
timeout 10msec
|
||||
{
|
||||
print network_time(), "when timeout", rec;
|
||||
Log::delay_finish(id, rec, token1);
|
||||
}
|
||||
}
|
||||
|
||||
# @TEST-START-NEXT
|
||||
# Basic delay() test two callbacks and two Log::delay_finish() calls.
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
local token1 = Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool {
|
||||
local delayed_for = network_time() - now;
|
||||
rec2$msg = fmt("%s delayed %s", rec2$msg, delayed_for);
|
||||
print network_time(), "post_delay_cb - 1", rec2, delayed_for;
|
||||
return T;
|
||||
});
|
||||
|
||||
local token2 = Log::delay(LOG, rec, function(rec2: Info, id2: Log::ID): bool {
|
||||
print network_time(), "post_delay_cb - 2", rec2;
|
||||
return T;
|
||||
});
|
||||
|
||||
when [id, rec, token1, token2] ( T == F )
|
||||
{
|
||||
}
|
||||
timeout 10msec
|
||||
{
|
||||
print network_time(), "when timeout", rec;
|
||||
Log::delay_finish(id, rec, token1);
|
||||
Log::delay_finish(id, rec, token2);
|
||||
}
|
||||
}
|
||||
|
||||
# @TEST-START-NEXT
|
||||
# The delay callback suppresses the log by return F.
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
local token = Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool {
|
||||
local delayed_for = network_time() - now;
|
||||
print network_time(), "post_delay_cb", rec2, delayed_for;
|
||||
return F;
|
||||
});
|
||||
|
||||
when [id, rec, token] ( T == F )
|
||||
{
|
||||
}
|
||||
timeout 10msec
|
||||
{
|
||||
print network_time(), "when timeout", rec;
|
||||
Log::delay_finish(id, rec, token);
|
||||
}
|
||||
}
|
||||
|
||||
# @TEST-START-NEXT
|
||||
# Do a delay and immediate release with a callback.
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
local token = Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool {
|
||||
local delayed_for = network_time() - now;
|
||||
print network_time(), "post_delay_cb", rec2, delayed_for;
|
||||
return T;
|
||||
});
|
||||
Log::delay_finish(id, rec, token);
|
||||
}
|
||||
|
|
@ -0,0 +1,69 @@
|
|||
# @TEST-DOC: Test some error cases
|
||||
|
||||
# @TEST-EXEC: zeek -b -r $TRACES/http/get.trace %INPUT
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER='$SCRIPTS/diff-remove-abspath | sed -r "s/0x[0-9a-z]+/0x<...>/g"' btest-diff .stderr
|
||||
|
||||
redef enum Log::ID += { LOG };
|
||||
|
||||
type Info: record {
|
||||
ts: time &log &default=network_time();
|
||||
};
|
||||
|
||||
event zeek_init()
|
||||
{
|
||||
# Log::delay() not within a Log::log_stream_policy hook
|
||||
Log::create_stream(LOG, [$columns=Info]);
|
||||
local rec = Info();
|
||||
local token = Log::delay(LOG, rec);
|
||||
Log::delay_finish(LOG, rec, token);
|
||||
}
|
||||
|
||||
@TEST-START-NEXT
|
||||
@load base/protocols/conn
|
||||
|
||||
hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID)
|
||||
{
|
||||
# Not the same record as the one from the hook.
|
||||
Log::delay(id, copy(rec));
|
||||
}
|
||||
|
||||
@TEST-START-NEXT
|
||||
@load base/protocols/conn
|
||||
@load base/protocols/dns
|
||||
|
||||
hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID)
|
||||
{
|
||||
# Wrong stream identifier
|
||||
Log::delay(DNS::LOG, rec);
|
||||
}
|
||||
|
||||
@TEST-START-NEXT
|
||||
@load base/protocols/conn
|
||||
|
||||
hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID)
|
||||
{
|
||||
# Wrong record for delay_finish()
|
||||
local token = Log::delay(id, rec);
|
||||
Log::delay_finish(id, copy(rec), token);
|
||||
}
|
||||
|
||||
@TEST-START-NEXT
|
||||
@load base/protocols/conn
|
||||
|
||||
hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID)
|
||||
{
|
||||
# Delay underflow.
|
||||
local token = Log::delay(id, rec);
|
||||
Log::delay_finish(id, rec, token);
|
||||
Log::delay_finish(id, rec, token);
|
||||
}
|
||||
|
||||
@TEST-START-NEXT
|
||||
@load base/protocols/conn
|
||||
|
||||
hook Conn::log_policy(rec: Conn::Info, id: Log::ID, filter: Log::Filter)
|
||||
{
|
||||
# Calling Log::delay() in a filter policy hook is an error.
|
||||
local token = Log::delay(id, rec);
|
||||
Log::delay_finish(id, rec, token);
|
||||
}
|
||||
|
|
@ -0,0 +1,58 @@
|
|||
# @TEST-DOC: Example using lookup_addr()
|
||||
|
||||
# @TEST-EXEC: zeek -b -r $TRACES/http/get.trace %INPUT
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff .stdout
|
||||
# @TEST-EXEC: btest-diff .stderr
|
||||
# @TEST-EXEC: zeek-cut -m ts uid id.orig_h orig_name id.resp_h resp_name < conn.log > conn.cut
|
||||
# @TEST-EXEC: btest-diff conn.cut
|
||||
|
||||
|
||||
# Enrich conn.log with lookup_addr() result
|
||||
@load base/protocols/conn
|
||||
|
||||
redef record Conn::Info += {
|
||||
orig_name: string &log &optional;
|
||||
resp_name: string &log &optional;
|
||||
};
|
||||
|
||||
hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID)
|
||||
{
|
||||
if ( id != Conn::LOG )
|
||||
return;
|
||||
|
||||
print network_time(), "log_stream_policy", id, rec;
|
||||
|
||||
local token1 = Log::delay(id, rec, function(rec2: Conn::Info, id2: Log::ID): bool {
|
||||
print network_time(), "token1 delay hook";
|
||||
return T;
|
||||
});
|
||||
local token2 = Log::delay(id, rec, function(rec2: Conn::Info, id2: Log::ID): bool {
|
||||
print network_time(), "token2 delay hook";
|
||||
return T;
|
||||
});
|
||||
|
||||
when [id, rec, token1] ( local orig_name = lookup_addr(rec$id$orig_h) )
|
||||
{
|
||||
rec$orig_name = orig_name;
|
||||
Log::delay_finish(id, rec, token1);
|
||||
}
|
||||
timeout 150msec
|
||||
{
|
||||
Reporter::warning(fmt("lookup_addr timeout for %s", rec$id$orig_h));
|
||||
}
|
||||
|
||||
when [id, rec, token2] ( local resp_name = lookup_addr(rec$id$resp_h) )
|
||||
{
|
||||
rec$resp_name = resp_name;
|
||||
Log::delay_finish(id, rec, token2);
|
||||
}
|
||||
timeout 150msec
|
||||
{
|
||||
Reporter::warning(fmt("lookup_addr timeout for %s", rec$id$resp_h));
|
||||
}
|
||||
}
|
||||
|
||||
event Pcap::file_done(path: string)
|
||||
{
|
||||
print network_time(), "Pcap::file_done";
|
||||
}
|
||||
|
|
@ -0,0 +1,87 @@
|
|||
# @TEST-DOC: Test the behavior when the same record is written twice. Each Log::write() is delayed independenly. In the test below, the second Log::write() is not delayed.
|
||||
|
||||
# @TEST-EXEC: zeek -B logging,tm -b -r $TRACES/http/get.trace test.zeek %INPUT
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stdout
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stderr
|
||||
|
||||
# @TEST-EXEC: touch test.log && zeek-cut -m -F'|' < test.log > test.cut
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test.cut
|
||||
|
||||
@TEST-START-FILE test.zeek
|
||||
|
||||
global packet_count = 0;
|
||||
event new_packet(c: connection, p: pkt_hdr)
|
||||
{
|
||||
++packet_count;
|
||||
print network_time(), "new_packet", packet_count;
|
||||
}
|
||||
|
||||
event Pcap::file_done(p: string)
|
||||
{
|
||||
print network_time(), "Pcap::file_done";
|
||||
}
|
||||
|
||||
redef enum Log::ID += {
|
||||
LOG
|
||||
};
|
||||
|
||||
type Info: record {
|
||||
ts: time &log;
|
||||
write_ts: time &log &optional;
|
||||
uid: string &log;
|
||||
msg: string &log;
|
||||
};
|
||||
|
||||
hook log_policy(rec: Info, id: Log::ID, filter: Log::Filter)
|
||||
{
|
||||
print network_time(), "log_policy", rec$uid, rec$msg;
|
||||
rec$write_ts = network_time();
|
||||
}
|
||||
|
||||
event zeek_init()
|
||||
{
|
||||
Log::create_stream(LOG, [$columns=Info, $path="test", $policy=log_policy]);
|
||||
}
|
||||
@TEST-END-FILE test.zeek
|
||||
|
||||
event new_connection(c: connection)
|
||||
{
|
||||
print network_time(), "new_connection", c$uid;
|
||||
local info = Info($ts=network_time(), $uid=c$uid, $msg="inital-value");
|
||||
Log::write(LOG, info);
|
||||
# This becomes visible on the first write.
|
||||
info$msg = "initial-value-second-write";
|
||||
Log::write(LOG, info);
|
||||
}
|
||||
|
||||
global write = 0;
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
++write;
|
||||
|
||||
# Second write is directly going to the filters.
|
||||
if ( write == 2 )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id, write, rec;
|
||||
|
||||
Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool {
|
||||
local delayed_for = network_time() - now;
|
||||
rec2$msg = fmt("%s delayed %s", rec2$msg, delayed_for);
|
||||
print network_time(), "post_delay_cb", rec2, delayed_for;
|
||||
return T;
|
||||
});
|
||||
|
||||
when [rec] ( T == F )
|
||||
{
|
||||
}
|
||||
timeout 10msec
|
||||
{
|
||||
print network_time(), "when timeout", rec;
|
||||
}
|
||||
}
|
||||
|
|
@ -0,0 +1,112 @@
|
|||
# @TEST-DOC: Test the behavior when a Log::write() happens within Log::log_stream_policy(), or within a post_delay_cb hook.
|
||||
|
||||
# @TEST-EXEC: zeek -B logging,tm -b -r $TRACES/http/get.trace test.zeek %INPUT
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stdout
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stderr
|
||||
|
||||
# @TEST-EXEC: touch test.log && zeek-cut -m -F'|' < test.log > test.cut
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test.cut
|
||||
#
|
||||
# @TEST-EXEC: touch test-other.log && zeek-cut -m -F'|' < test-other.log > test-other.cut
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test-other.cut
|
||||
|
||||
@TEST-START-FILE test.zeek
|
||||
|
||||
# Debug printing
|
||||
global packet_count = 0;
|
||||
event new_packet(c: connection, p: pkt_hdr)
|
||||
{
|
||||
++packet_count;
|
||||
print network_time(), "new_packet", packet_count;
|
||||
}
|
||||
|
||||
event Pcap::file_done(p: string)
|
||||
{
|
||||
print network_time(), "Pcap::file_done";
|
||||
}
|
||||
|
||||
redef enum Log::ID += {
|
||||
LOG,
|
||||
LOG_OTHER,
|
||||
};
|
||||
|
||||
type Info: record {
|
||||
ts: time &log;
|
||||
write_ts: time &log &optional;
|
||||
uid: string &log;
|
||||
msg: string &log;
|
||||
};
|
||||
|
||||
hook log_policy(rec: Info, id: Log::ID, filter: Log::Filter)
|
||||
{
|
||||
print network_time(), "log_policy", rec$uid, id, rec$msg;
|
||||
rec$write_ts = network_time();
|
||||
}
|
||||
|
||||
event zeek_init()
|
||||
{
|
||||
Log::create_stream(LOG, [$columns=Info, $path="test", $policy=log_policy]);
|
||||
Log::create_stream(LOG_OTHER, [$columns=Info, $path="test-other", $policy=log_policy]);
|
||||
}
|
||||
|
||||
event new_connection(c: connection)
|
||||
{
|
||||
print network_time(), "new_connection", c$uid;
|
||||
local info = Info($ts=network_time(), $uid=c$uid, $msg="inital-value");
|
||||
Log::write(LOG, info);
|
||||
}
|
||||
@TEST-END-FILE test.zeek
|
||||
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
local now = network_time();
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
# Send to the other log.
|
||||
Log::write(LOG_OTHER, rec);
|
||||
|
||||
Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool {
|
||||
local delayed_for = network_time() - now;
|
||||
rec2$msg = fmt("%s delayed %s", rec2$msg, delayed_for);
|
||||
print network_time(), "post_delay_cb", rec2, delayed_for;
|
||||
return T;
|
||||
});
|
||||
|
||||
when [rec] ( T == F )
|
||||
{
|
||||
}
|
||||
timeout 10msec
|
||||
{
|
||||
print network_time(), "when timeout", rec;
|
||||
}
|
||||
}
|
||||
|
||||
@TEST-START-NEXT
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
local now = network_time();
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool {
|
||||
local delayed_for = network_time() - now;
|
||||
rec2$msg = fmt("%s delayed %s", rec2$msg, delayed_for);
|
||||
print network_time(), "post_delay_cb", rec2, delayed_for;
|
||||
Log::write(LOG_OTHER, rec2);
|
||||
|
||||
return T;
|
||||
});
|
||||
|
||||
when [rec] ( T == F )
|
||||
{
|
||||
}
|
||||
timeout 10msec
|
||||
{
|
||||
print network_time(), "when timeout", rec;
|
||||
}
|
||||
}
|
||||
|
|
@ -0,0 +1,142 @@
|
|||
# @TEST-DOC: Changing queue parameters while writes are pending.
|
||||
|
||||
# @TEST-EXEC: zeek -B logging,tm -b -r $TRACES/http/get.trace test.zeek %INPUT
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stdout
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stderr
|
||||
|
||||
# @TEST-EXEC: zeek-cut -m -F'|' < test.log > test.cut
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test.cut
|
||||
|
||||
@TEST-START-FILE test.zeek
|
||||
# Used by all tests below.
|
||||
|
||||
# Debug printing
|
||||
global packet_count = 0;
|
||||
|
||||
redef enum Log::ID += {
|
||||
LOG
|
||||
};
|
||||
|
||||
type Info: record {
|
||||
ts: time &log;
|
||||
post_ts: time &log &optional;
|
||||
write_ts: time &log &optional;
|
||||
msg: string &log;
|
||||
};
|
||||
|
||||
event new_packet(c: connection, p: pkt_hdr)
|
||||
{
|
||||
++packet_count;
|
||||
print network_time(), "new_packet", packet_count;
|
||||
local info = Info($ts=network_time(), $msg=fmt("packet number %s", packet_count));
|
||||
Log::write(LOG, info);
|
||||
}
|
||||
|
||||
|
||||
hook log_policy(rec: Info, id: Log::ID, filter: Log::Filter)
|
||||
{
|
||||
print network_time(), "log_policy";
|
||||
rec$write_ts = network_time();
|
||||
}
|
||||
|
||||
event Pcap::file_done(p: string)
|
||||
{
|
||||
print network_time(), "Pcap::file_done", p;
|
||||
}
|
||||
|
||||
@TEST-END-FILE test.zeek
|
||||
# Delay records for a long time, reduce queue size after 10 packets to 3.
|
||||
|
||||
event zeek_init()
|
||||
{
|
||||
Log::create_stream(LOG, [
|
||||
$columns=Info,
|
||||
$path="test",
|
||||
$policy=log_policy,
|
||||
$max_delay_interval=10sec,
|
||||
]);
|
||||
}
|
||||
|
||||
event new_packet(c: connection, p: pkt_hdr) &priority=-5
|
||||
{
|
||||
if ( packet_count == 10 )
|
||||
{
|
||||
print network_time(), "set_max_delay_queue_size to 3";
|
||||
Log::set_max_delay_queue_size(LOG, 3);
|
||||
}
|
||||
}
|
||||
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
Log::delay(id, rec, function[now](rec2: Info, id2: Log::ID): bool {
|
||||
local delayed_for = network_time() - now;
|
||||
rec2$post_ts = network_time();
|
||||
print network_time(), "post_delay_cb", rec2, delayed_for;
|
||||
return T;
|
||||
});
|
||||
|
||||
}
|
||||
|
||||
# @TEST-START-NEXT
|
||||
#
|
||||
# Delay records for a long time, reduce queue size after 10 packets to 3,
|
||||
# re-delay all records once, provoking failure to free any space in the
|
||||
# queue.
|
||||
#
|
||||
redef record Info += {
|
||||
redelayed: bool &default=F;
|
||||
};
|
||||
|
||||
event zeek_init()
|
||||
{
|
||||
Log::create_stream(LOG, [
|
||||
$columns=Info,
|
||||
$path="test",
|
||||
$policy=log_policy,
|
||||
$max_delay_interval=10sec,
|
||||
]);
|
||||
}
|
||||
|
||||
function post_delay_cb(rec: Info, id: Log::ID): bool
|
||||
{
|
||||
if ( ! rec$redelayed )
|
||||
{
|
||||
print network_time(), "post_delay_cb - re-delay", rec;
|
||||
rec$post_ts = network_time();
|
||||
rec$redelayed = T;
|
||||
Log::delay(id, rec, post_delay_cb);
|
||||
return T;
|
||||
}
|
||||
|
||||
|
||||
print network_time(), "post_delay_cb - done", rec;
|
||||
return T;
|
||||
}
|
||||
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
Log::delay(id, rec, post_delay_cb);
|
||||
}
|
||||
|
||||
event new_packet(c: connection, p: pkt_hdr) &priority=-5
|
||||
{
|
||||
if ( packet_count == 10 )
|
||||
{
|
||||
print network_time(), "set_max_delay_queue_size to 3";
|
||||
Log::set_max_delay_queue_size(LOG, 3);
|
||||
}
|
||||
}
|
||||
|
|
@ -0,0 +1,83 @@
|
|||
# @TEST-DOC: Delay queue testing.
|
||||
|
||||
# @TEST-EXEC: zeek -B logging,tm -b -r $TRACES/http/get.trace test.zeek %INPUT
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stdout
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stderr
|
||||
|
||||
# @TEST-EXEC: zeek-cut -m -F'|' < test.log > test.cut
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test.cut
|
||||
|
||||
@TEST-START-FILE test.zeek
|
||||
# Used by all tests below.
|
||||
|
||||
# Debug printing
|
||||
global packet_count = 0;
|
||||
|
||||
redef enum Log::ID += {
|
||||
LOG
|
||||
};
|
||||
|
||||
type Info: record {
|
||||
ts: time &log;
|
||||
post_ts: time &log &optional;
|
||||
write_ts: time &log &optional;
|
||||
msg: string &log;
|
||||
};
|
||||
|
||||
event new_packet(c: connection, p: pkt_hdr)
|
||||
{
|
||||
++packet_count;
|
||||
print network_time(), "new_packet", packet_count, "queue size", Log::get_delay_queue_size(LOG);
|
||||
local info = Info($ts=network_time(), $msg=fmt("packet number %s", packet_count));
|
||||
Log::write(LOG, info);
|
||||
print network_time(), "queue_size post write", Log::get_delay_queue_size(LOG);
|
||||
}
|
||||
|
||||
|
||||
hook log_policy(rec: Info, id: Log::ID, filter: Log::Filter)
|
||||
{
|
||||
print network_time(), "log_policy";
|
||||
rec$write_ts = network_time();
|
||||
}
|
||||
|
||||
event Pcap::file_done(p: string)
|
||||
{
|
||||
print network_time(), "Pcap::file_done", p;
|
||||
}
|
||||
|
||||
@TEST-END-FILE test.zeek
|
||||
|
||||
event zeek_init()
|
||||
{
|
||||
print network_time(), "queue_size non-existing", Log::get_delay_queue_size(LOG);
|
||||
Log::create_stream(LOG, [
|
||||
$columns=Info,
|
||||
$path="test",
|
||||
$policy=log_policy,
|
||||
$max_delay_interval=1msec,
|
||||
]);
|
||||
|
||||
print network_time(), "queue_size existing", Log::get_delay_queue_size(LOG);
|
||||
}
|
||||
|
||||
event zeek_done()
|
||||
{
|
||||
print network_time(), "queue_size done", Log::get_delay_queue_size(LOG);
|
||||
}
|
||||
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
Log::delay(id, rec, function[now](rec2: Info, id2: Log::ID): bool {
|
||||
local delayed_for = network_time() - now;
|
||||
rec2$post_ts = network_time();
|
||||
print network_time(), "post_delay_cb", rec2, delayed_for;
|
||||
return T;
|
||||
});
|
||||
}
|
||||
|
|
@ -0,0 +1,340 @@
|
|||
# @TEST-DOC: Delay queue testing.
|
||||
|
||||
# @TEST-EXEC: zeek -B logging,tm -b -r $TRACES/http/get.trace test.zeek %INPUT
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stdout
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stderr
|
||||
|
||||
# @TEST-EXEC: zeek-cut -m -F'|' < test.log > test.cut
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test.cut
|
||||
|
||||
@TEST-START-FILE test.zeek
|
||||
# Used by all tests below.
|
||||
|
||||
# Debug printing
|
||||
global packet_count = 0;
|
||||
|
||||
redef enum Log::ID += {
|
||||
LOG
|
||||
};
|
||||
|
||||
type Info: record {
|
||||
ts: time &log;
|
||||
post_ts: time &log &optional;
|
||||
write_ts: time &log &optional;
|
||||
msg: string &log;
|
||||
};
|
||||
|
||||
event new_packet(c: connection, p: pkt_hdr)
|
||||
{
|
||||
++packet_count;
|
||||
print network_time(), "new_packet", packet_count;
|
||||
local info = Info($ts=network_time(), $msg=fmt("packet number %s", packet_count));
|
||||
Log::write(LOG, info);
|
||||
}
|
||||
|
||||
|
||||
hook log_policy(rec: Info, id: Log::ID, filter: Log::Filter)
|
||||
{
|
||||
print network_time(), "log_policy";
|
||||
rec$write_ts = network_time();
|
||||
}
|
||||
|
||||
event Pcap::file_done(p: string)
|
||||
{
|
||||
print network_time(), "Pcap::file_done", p;
|
||||
}
|
||||
|
||||
@TEST-END-FILE test.zeek
|
||||
|
||||
# Delay every record by 1msec.
|
||||
event zeek_init()
|
||||
{
|
||||
Log::create_stream(LOG, [
|
||||
$columns=Info,
|
||||
$path="test",
|
||||
$policy=log_policy,
|
||||
$max_delay_interval=1msec,
|
||||
]);
|
||||
}
|
||||
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
Log::delay(id, rec, function[now](rec2: Info, id2: Log::ID): bool {
|
||||
local delayed_for = network_time() - now;
|
||||
rec2$post_ts = network_time();
|
||||
print network_time(), "post_delay_cb", rec2, delayed_for;
|
||||
return T;
|
||||
});
|
||||
|
||||
}
|
||||
|
||||
# @TEST-START-NEXT
|
||||
#
|
||||
# Delay every record, but call Log::delay_finish() immediately afterwards
|
||||
# through an event.
|
||||
|
||||
event zeek_init()
|
||||
{
|
||||
Log::create_stream(LOG, [
|
||||
$columns=Info,
|
||||
$path="test",
|
||||
$policy=log_policy,
|
||||
$max_delay_interval=1msec,
|
||||
]);
|
||||
}
|
||||
|
||||
event release_delay(rec: Info, token: Log::DelayToken)
|
||||
{
|
||||
Log::delay_finish(LOG, rec, token);
|
||||
}
|
||||
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id;
|
||||
|
||||
local token = Log::delay(id, rec, function[now](rec2: Info, id2: Log::ID): bool {
|
||||
local delayed_for = network_time() - now;
|
||||
rec2$post_ts = network_time();
|
||||
print network_time(), "post_delay_cb", rec2, delayed_for;
|
||||
return T;
|
||||
});
|
||||
|
||||
event release_delay(rec, token);
|
||||
}
|
||||
|
||||
# @TEST-START-NEXT
|
||||
#
|
||||
# Delay every record, and for every other record call Log::delay_finish()
|
||||
# immediately afterwards via an event.
|
||||
|
||||
event zeek_init()
|
||||
{
|
||||
Log::create_stream(LOG, [
|
||||
$columns=Info,
|
||||
$path="test",
|
||||
$policy=log_policy,
|
||||
$max_delay_interval=1msec,
|
||||
]);
|
||||
}
|
||||
|
||||
event release_delay(rec: Info, token: Log::DelayToken)
|
||||
{
|
||||
Log::delay_finish(LOG, rec, token);
|
||||
}
|
||||
|
||||
global write = 0;
|
||||
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
++write;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id;
|
||||
|
||||
local token = Log::delay(id, rec, function[now](rec2: Info, id2: Log::ID): bool {
|
||||
local delayed_for = network_time() - now;
|
||||
rec2$post_ts = network_time();
|
||||
print network_time(), "post_delay_cb", rec2, delayed_for;
|
||||
return T;
|
||||
});
|
||||
|
||||
if ( write % 2 == 1 )
|
||||
event release_delay(rec, token);
|
||||
|
||||
}
|
||||
|
||||
# @TEST-START-NEXT
|
||||
|
||||
# Delay every entry by 10 seconds, but set queue size to 5 such that
|
||||
# entries are evicted when the queue size is reached.
|
||||
|
||||
event zeek_init()
|
||||
{
|
||||
Log::create_stream(LOG, [
|
||||
$columns=Info,
|
||||
$path="test",
|
||||
$policy=log_policy,
|
||||
$max_delay_interval=10sec,
|
||||
$max_delay_queue_size=5,
|
||||
]);
|
||||
}
|
||||
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
Log::delay(id, rec, function[now](rec2: Info, id2: Log::ID): bool {
|
||||
local delayed_for = network_time() - now;
|
||||
rec2$post_ts = network_time();
|
||||
print network_time(), "post_delay_cb", rec2, delayed_for;
|
||||
return T;
|
||||
});
|
||||
}
|
||||
|
||||
|
||||
# @TEST-START-NEXT
|
||||
|
||||
# Re-delaying works even if that results in more forceful expiration.
|
||||
redef record Info += {
|
||||
redelayed: bool &default=F;
|
||||
};
|
||||
|
||||
event zeek_init()
|
||||
{
|
||||
Log::create_stream(LOG, [
|
||||
$columns=Info,
|
||||
$path="test",
|
||||
$policy=log_policy,
|
||||
$max_delay_interval=10sec,
|
||||
$max_delay_queue_size=5,
|
||||
]);
|
||||
}
|
||||
|
||||
function post_delay_cb(rec: Info, id: Log::ID): bool
|
||||
{
|
||||
if ( ! rec$redelayed )
|
||||
{
|
||||
print network_time(), "post_delay_cb - re-delay", rec;
|
||||
rec$post_ts = network_time();
|
||||
rec$redelayed = T;
|
||||
Log::delay(id, rec, post_delay_cb);
|
||||
return T;
|
||||
}
|
||||
|
||||
|
||||
print network_time(), "post_delay_cb - done", rec;
|
||||
return T;
|
||||
}
|
||||
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
Log::delay(id, rec, post_delay_cb);
|
||||
}
|
||||
|
||||
# @TEST-START-NEXT
|
||||
|
||||
# Re-delay once after the delay expired.
|
||||
redef record Info += {
|
||||
redelayed: bool &default=F;
|
||||
};
|
||||
|
||||
event zeek_init()
|
||||
{
|
||||
Log::create_stream(LOG, [
|
||||
$columns=Info,
|
||||
$path="test",
|
||||
$policy=log_policy,
|
||||
$max_delay_interval=1msec,
|
||||
]);
|
||||
}
|
||||
|
||||
function post_delay_cb(rec: Info, id: Log::ID): bool
|
||||
{
|
||||
if ( ! rec$redelayed )
|
||||
{
|
||||
print network_time(), "post_delay_cb - re-delay", rec;
|
||||
rec$post_ts = network_time();
|
||||
rec$redelayed = T;
|
||||
Log::delay(id, rec, post_delay_cb);
|
||||
return T;
|
||||
}
|
||||
|
||||
|
||||
print network_time(), "post_delay_cb - done", rec;
|
||||
return T;
|
||||
}
|
||||
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
Log::delay(id, rec, post_delay_cb);
|
||||
}
|
||||
|
||||
# @TEST-START-NEXT
|
||||
|
||||
# Re-delay once after Log::delay_finish()
|
||||
redef record Info += {
|
||||
redelayed: bool &default=F;
|
||||
};
|
||||
|
||||
event release_delay(rec: Info, token: Log::DelayToken)
|
||||
{
|
||||
Log::delay_finish(LOG, rec, token);
|
||||
}
|
||||
|
||||
|
||||
event zeek_init()
|
||||
{
|
||||
Log::create_stream(LOG, [
|
||||
$columns=Info,
|
||||
$path="test",
|
||||
$policy=log_policy,
|
||||
$max_delay_interval=1msec,
|
||||
]);
|
||||
}
|
||||
|
||||
function post_delay_cb(rec: Info, id: Log::ID): bool
|
||||
{
|
||||
if ( ! rec$redelayed )
|
||||
{
|
||||
print network_time(), "post_delay_cb - re-delay", rec;
|
||||
rec$post_ts = network_time();
|
||||
rec$redelayed = T;
|
||||
local token = Log::delay(id, rec, post_delay_cb);
|
||||
|
||||
event release_delay(rec, token);
|
||||
return T;
|
||||
}
|
||||
|
||||
|
||||
print network_time(), "post_delay_cb - done", rec;
|
||||
return T;
|
||||
}
|
||||
|
||||
hook Log::log_stream_policy(rec: Info, id: Log::ID)
|
||||
{
|
||||
if ( id != LOG )
|
||||
return;
|
||||
|
||||
local now = network_time();
|
||||
|
||||
print now, "log_stream_policy", id, rec;
|
||||
|
||||
local token = Log::delay(id, rec, post_delay_cb);
|
||||
|
||||
event release_delay(rec, token);
|
||||
}
|
||||
|
|
@ -0,0 +1,55 @@
|
|||
# @TEST-DOC: Test bad signature of callback function.
|
||||
|
||||
# @TEST-EXEC-FAIL: zeek -b -r $TRACES/http/get.trace %INPUT
|
||||
# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stderr
|
||||
|
||||
@load base/protocols/conn
|
||||
|
||||
# PostDelayCallback needs to return a bool
|
||||
function post_delay_cb(rec: Conn::Info, id: Log::ID)
|
||||
{
|
||||
print "post_delay_cb";
|
||||
}
|
||||
|
||||
hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID)
|
||||
{
|
||||
Log::delay(id, rec, post_delay_cb);
|
||||
}
|
||||
|
||||
|
||||
# @TEST-START-NEXT
|
||||
@load base/protocols/conn
|
||||
|
||||
# PostDelayCallback needs to return a bool
|
||||
function post_delay_cb(rec: Conn::Info, id: Log::ID): count
|
||||
{
|
||||
print "post_delay_cb";
|
||||
return 1;
|
||||
}
|
||||
|
||||
hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID)
|
||||
{
|
||||
Log::delay(id, rec, post_delay_cb);
|
||||
}
|
||||
|
||||
@TEST-START-NEXT
|
||||
# Bad token type 1
|
||||
@load base/protocols/conn
|
||||
|
||||
hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID)
|
||||
{
|
||||
# Wrong token type for delay_finish()
|
||||
local token = Log::delay(id, rec);
|
||||
Log::delay_finish(id, rec, "42");
|
||||
}
|
||||
|
||||
@TEST-START-NEXT
|
||||
# Bad token type 2
|
||||
@load base/protocols/conn
|
||||
|
||||
hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID)
|
||||
{
|
||||
# Wrong token type for delay_finish()
|
||||
local token = Log::delay(id, rec);
|
||||
Log::delay_finish(id, rec, 42);
|
||||
}
|
||||
Loading…
Add table
Add a link
Reference in a new issue