diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-2/test.log b/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-2/test.log new file mode 100644 index 0000000000..67a545a9d6 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-2/test.log @@ -0,0 +1,10 @@ +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open 2020-09-24-06-04-38 +#fields t status +#types time string +1600927478.316159 bar +#close 2020-09-24-06-04-38 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-3/test.log b/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-3/test.log new file mode 100644 index 0000000000..3d83ad6778 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-3/test.log @@ -0,0 +1,10 @@ +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open 2020-09-24-06-04-38 +#fields t status +#types time string +1600927478.528919 bar +#close 2020-09-24-06-04-38 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-4/test.log b/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-4/test.log new file mode 100644 index 0000000000..185738c74e --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-4/test.log @@ -0,0 +1,10 @@ +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open 2020-09-24-06-04-38 +#fields t status +#types time string +1600927478.733541 bar +#close 2020-09-24-06-04-38 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-5/other.log b/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-5/other.log new file mode 100644 index 0000000000..3308b24bcc --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-5/other.log @@ -0,0 +1,10 @@ +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path other +#open 2020-09-24-06-42-48 +#fields t status +#types time string +1600929768.810574 baz +#close 2020-09-24-06-42-48 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-5/test.log b/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-5/test.log new file mode 100644 index 0000000000..58e4869c9b --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-5/test.log @@ -0,0 +1,10 @@ +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open 2020-09-24-06-42-48 +#fields t status +#types time string +1600929768.810574 bar +#close 2020-09-24-06-42-48 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-6/other.log b/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-6/other.log new file mode 100644 index 0000000000..82d97f3a0b --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-6/other.log @@ -0,0 +1,11 @@ +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path other +#open 2020-09-24-06-45-34 +#fields t status +#types time string +1600929934.868883 foo +1600929934.868883 bar +#close 2020-09-24-06-45-34 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-6/test.log b/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-6/test.log new file mode 100644 index 0000000000..61acad9811 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-6/test.log @@ -0,0 +1,10 @@ +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open 2020-09-24-06-45-34 +#fields t status +#types time string +1600929934.868883 bar +#close 2020-09-24-06-45-34 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-7/test.log b/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-7/test.log new file mode 100644 index 0000000000..ce4bda80a6 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.hooks-7/test.log @@ -0,0 +1,10 @@ +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open 2020-09-24-19-34-37 +#fields t status +#types time string +1600976077.343410 bar +#close 2020-09-24-19-34-37 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.hooks/test.log b/testing/btest/Baseline/scripts.base.frameworks.logging.hooks/test.log new file mode 100644 index 0000000000..37aec84588 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.hooks/test.log @@ -0,0 +1,10 @@ +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open 2020-09-24-06-04-38 +#fields t status +#types time string +1600927478.107907 foo +#close 2020-09-24-06-04-38 diff --git a/testing/btest/scripts/base/frameworks/logging/hooks.zeek b/testing/btest/scripts/base/frameworks/logging/hooks.zeek new file mode 100644 index 0000000000..4c22c8da92 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/hooks.zeek @@ -0,0 +1,169 @@ +# Tests for policy hooks on log filters. +# +# @TEST-EXEC: zeek -b test.zeek %INPUT +# @TEST-EXEC: btest-diff test.log +# @TEST-EXEC: test -f other.log && btest-diff other.log || true + +@TEST-START-FILE test.zeek +# This provides a simple test module harness, used by all of the individual tests below. +module Test; + +export { + # Create a new ID for our log stream + redef enum Log::ID += { LOG, LOG_OTHER }; + + # Create a corresponding policy hook: + global log_policy: Log::PolicyHook; + + # Make up a log format for our tests + type Info: record { + t: time; + status: string; + } &log; +} + +event zeek_init() &priority=2 + { + Log::create_stream(Test::LOG, [$columns=Info, $path="test", $policy=log_policy]); + Log::create_stream(Test::LOG_OTHER, [$columns=Info, $path="test_other"]); + } +@TEST-END-FILE test.zeek + +# Verify basic argument passing -- id and filter should be accessible +# and have expected values. The hook should not catch. + +hook Test::log_policy(rec: Test::Info, id: Log::ID, filter: Log::Filter) + { + if ( id != Test::LOG || filter$name != "default" ) + break; + } + +event zeek_init() + { + Log::write(Test::LOG, [$t=network_time(), $status="foo"]); + } + +@TEST-START-NEXT + +# Verify that a policy hook can veto select log records. + +hook Test::log_policy(rec: Test::Info, id: Log::ID, filter: Log::Filter) + { + if ( rec$status == "foo" ) + break; + } + +event zeek_init() + { + Log::write(Test::LOG, [$t=network_time(), $status="foo"]); + Log::write(Test::LOG, [$t=network_time(), $status="bar"]); + } + +@TEST-START-NEXT + +# Verify that a policy hook can alter the log entry. +# +# NOTE: doing this is dangerous; the change survives into log writes +# resulting on other filters that get processed after the current one, +# and the order of filters is undefined. We just test here that the +# modification doesn't cause unexpected errors. + +hook Test::log_policy(rec: Test::Info, id: Log::ID, filter: Log::Filter) + { + rec$status = "bar"; + } + +event zeek_init() + { + Log::write(Test::LOG, [$t=network_time(), $status="foo"]); + } + +@TEST-START-NEXT + +# Verify that multiple hook handlers can get registered and their +# priorities work as expected. (More of a generic hook test than +# logging-specific, really.) +# +# The higher-priority hook filters out the only log record; the +# lower-priority one should not get an opportunity to change it. + +hook Test::log_policy(rec: Test::Info, id: Log::ID, filter: Log::Filter) &priority=10 + { + if ( rec$status == "foo" ) + rec$status = "baz"; + } + +hook Test::log_policy(rec: Test::Info, id: Log::ID, filter: Log::Filter) &priority=20 + { + rec$status = "bar"; + } + +event zeek_init() + { + Log::write(Test::LOG, [$t=network_time(), $status="foo"]); + } + +@TEST-START-NEXT + +# Verify that the stream-level policy gets inherited into additional +# filters. The single hook handler should get invoked for both of the +# log filters., and alters them depending on the filter. + +hook Test::log_policy(rec: Test::Info, id: Log::ID, filter: Log::Filter) + { + if ( filter$name == "default" ) + rec$status = "bar"; + if ( filter$name == "other" ) + rec$status = "baz"; + } + +event zeek_init() + { + Log::add_filter(Test::LOG, [$name="other", $path="other"]); + Log::write(Test::LOG, [$t=network_time(), $status="foo"]); + } + +@TEST-START-NEXT + +# Verify that filters can override the stream-level policy. The +# stream-level policy rejects select records; the overriding one is +# permissive. + +hook Test::log_policy(rec: Test::Info, id: Log::ID, filter: Log::Filter) + { + if ( rec$status == "foo" ) + break; + } + +hook log_policy_permissible(rec: Test::Info, id: Log::ID, filter: Log::Filter) + { + } + +event zeek_init() + { + Log::add_filter(Test::LOG, [$name="other", $path="other", $policy=log_policy_permissible]); + Log::write(Test::LOG, [$t=network_time(), $status="foo"]); + Log::write(Test::LOG, [$t=network_time(), $status="bar"]); + } + +@TEST-START-NEXT + +# Verify that filters can define their own policy hooks when the +# stream doesn't provide any. The Test::LOG_OTHER stream does not. + +hook my_log_policy(rec: Test::Info, id: Log::ID, filter: Log::Filter) + { + if ( rec$status == "foo" ) + break; + } + +event zeek_init() + { + local filter = Log::get_filter(Test::LOG_OTHER, "default"); + filter$path = "test"; + filter$policy = my_log_policy; + Log::add_filter(Test::LOG_OTHER, filter); + + Log::write(Test::LOG_OTHER, [$t=network_time(), $status="foo"]); + Log::write(Test::LOG_OTHER, [$t=network_time(), $status="bar"]); + } diff --git a/testing/btest/scripts/base/frameworks/logging/pred.zeek b/testing/btest/scripts/base/frameworks/logging/pred.zeek index aa89fdf504..9f59122081 100644 --- a/testing/btest/scripts/base/frameworks/logging/pred.zeek +++ b/testing/btest/scripts/base/frameworks/logging/pred.zeek @@ -31,7 +31,7 @@ event zeek_init() Log::add_filter(Test::LOG, [$name="f1", $path="test.success", $pred=function(rec: Log): bool { return rec$status == "success"; }]); Log::add_filter(Test::LOG, [$name="f2", $path="test.failure", $pred=fail]); - local cid = [$orig_h=1.2.3.4, $orig_p=1234/tcp, $resp_h=2.3.4.5, $resp_p=80/tcp]; + local cid = [$orig_h=1.2.3.4, $orig_p=1234/tcp, $resp_h=2.3.4.5, $resp_p=80/tcp]; local r: Log = [$t=network_time(), $id=cid, $status="success"]; Log::write(Test::LOG, r); Log::write(Test::LOG, [$t=network_time(), $id=cid, $status="failure", $country="US"]);