Rewrite weird logging.

This commit rewrites the way that weirds are logged and fixes a number
of issues on the way. Most prominently, flow weirds now actually log
information about the flow that they occur in (before this change, they
only logged the name of the weird, which is only marginally helpful).

Besides restructuring how weird logging works internally, weirds can now
also be generated by calling Weird::weird with the info record directly,
allowing more fine-granular passing of information. This is e.g. used
for DNS weirds, which do not have the connection record available any
more when they are generated (before data like the connection ID was
just not logged in these instances).

Addresses BIT-1578
This commit is contained in:
Johanna Amann 2016-06-15 13:31:37 -07:00
parent 41eb50f9db
commit 697b2748f5
6 changed files with 163 additions and 136 deletions

View file

@ -16,31 +16,47 @@ module Weird;
export {
## The weird logging stream identifier.
redef enum Log::ID += { LOG };
redef enum Notice::Type += {
## Generic unusual but notice-worthy weird activity.
Activity,
};
## The record type which contains the column fields of the weird log.
## The record which is used for representing and logging weirds.
type Info: record {
## The time when the weird occurred.
ts: time &log;
## If a connection is associated with this weird, this will be
## the connection's unique ID.
uid: string &log &optional;
## conn_id for the optional connection.
id: conn_id &log &optional;
## A shorthand way of giving the uid and id to a weird.
conn: connection &optional;
## The name of the weird that occurred.
name: string &log;
## Additional information accompanying the weird if any.
addl: string &log &optional;
## Indicate if this weird was also turned into a notice.
notice: bool &log &default=F;
notice: bool &log &default=F;
## The peer that originated this weird. This is helpful in
## cluster deployments if a particular cluster node is having
## trouble to help identify which node is having trouble.
peer: string &log &optional;
peer: string &log &optional &default=peer_description;
## This field is to be provided when a weird is generated for
## the purpose of deduplicating weirds. The identifier string
## should be unique for a single instance of the weird. This field
## is used to define when a weird is conceptually a duplicate of
## a previous weird.
identifier: string &optional;
};
## Types of actions that may be taken when handling weird activity events.
@ -59,13 +75,13 @@ export {
## Log the weird event once per originator host.
ACTION_LOG_PER_ORIG,
## Always generate a notice associated with the weird event.
ACTION_NOTICE,
ACTION_NOTICE,
## Generate a notice associated with the weird event only once.
ACTION_NOTICE_ONCE,
## Generate a notice for the weird event once per connection.
ACTION_NOTICE_PER_CONN,
## Generate a notice for the weird event once per originator host.
ACTION_NOTICE_PER_ORIG,
ACTION_NOTICE_PER_ORIG,
};
## A table specifying default/recommended actions per weird type.
@ -246,7 +262,7 @@ export {
"bad_IP_checksum", "bad_TCP_checksum", "bad_UDP_checksum",
"bad_ICMP_checksum",
} &redef;
## This table is used to track identifier and name pairs that should be
## temporarily ignored because the problem has already been reported.
## This helps reduce the volume of high volume weirds by only allowing
@ -267,9 +283,11 @@ export {
##
## rec: The weird columns about to be logged to the weird stream.
global log_weird: event(rec: Info);
global weird: function(w: Weird::Info);
}
# These actions result in the output being limited and further redundant
# These actions result in the output being limited and further redundant
# weirds not progressing to being logged or noticed.
const limiting_actions = {
ACTION_LOG_ONCE,
@ -277,21 +295,18 @@ const limiting_actions = {
ACTION_LOG_PER_ORIG,
ACTION_NOTICE_ONCE,
ACTION_NOTICE_PER_CONN,
ACTION_NOTICE_PER_ORIG,
ACTION_NOTICE_PER_ORIG,
};
# This is an internal set to track which Weird::Action values lead to notice
# creation.
const notice_actions = {
ACTION_NOTICE,
ACTION_NOTICE_PER_CONN,
ACTION_NOTICE_PER_ORIG,
ACTION_NOTICE,
ACTION_NOTICE_PER_CONN,
ACTION_NOTICE_PER_ORIG,
ACTION_NOTICE_ONCE,
};
# Used to pass the optional connection into report().
global current_conn: connection;
event bro_init() &priority=5
{
Log::create_stream(Weird::LOG, [$columns=Info, $ev=log_weird, $path="weird"]);
@ -302,110 +317,118 @@ function flow_id_string(src: addr, dst: addr): string
return fmt("%s -> %s", src, dst);
}
function report(t: time, name: string, identifier: string, have_conn: bool, addl: string)
function weird(w: Weird::Info)
{
local action = actions[name];
local action = actions[w$name];
local identifier = "";
if ( w?$identifier )
identifier = w$identifier;
else
{
if ( w?$id )
identifier = id_string(w$id);
}
# If this weird is to be ignored let's drop out of here very early.
if ( action == ACTION_IGNORE || [name, identifier] in weird_ignore )
if ( action == ACTION_IGNORE || [w$name, identifier] in weird_ignore )
return;
if ( w?$conn )
{
w$uid = w$conn$uid;
w$id = w$conn$id;
}
if ( w?$id )
{
if ( [w$id$orig_h, w$name] in ignore_hosts ||
[w$id$resp_h, w$name] in ignore_hosts )
return;
}
if ( action in limiting_actions )
{
if ( action in notice_actions )
{
# Handle notices
if ( have_conn && action == ACTION_NOTICE_PER_ORIG )
identifier = fmt("%s", current_conn$id$orig_h);
if ( w?$id && action == ACTION_NOTICE_PER_ORIG )
identifier = fmt("%s", w$id$orig_h);
else if ( action == ACTION_NOTICE_ONCE )
identifier = "";
# If this weird was already noticed then we're done.
if ( [name, identifier] in did_notice )
if ( [w$name, identifier] in did_notice )
return;
add did_notice[name, identifier];
add did_notice[w$name, identifier];
}
else
{
# Handle logging.
if ( have_conn && action == ACTION_LOG_PER_ORIG )
identifier = fmt("%s", current_conn$id$orig_h);
if ( w?$id && action == ACTION_LOG_PER_ORIG )
identifier = fmt("%s", w$id$orig_h);
else if ( action == ACTION_LOG_ONCE )
identifier = "";
# If this weird was already logged then we're done.
if ( [name, identifier] in did_log )
if ( [w$name, identifier] in did_log )
return;
add did_log[name, identifier];
add did_log[w$name, identifier];
}
}
# Create the Weird::Info record.
local info: Info;
info$ts = t;
info$name = name;
info$peer = peer_description;
if ( addl != "" )
info$addl = addl;
if ( have_conn )
{
info$uid = current_conn$uid;
info$id = current_conn$id;
}
if ( action in notice_actions )
{
info$notice = T;
w$notice = T;
local n: Notice::Info;
n$note = Activity;
n$msg = info$name;
if ( have_conn )
n$conn = current_conn;
if ( info?$addl )
n$sub = info$addl;
n$msg = w$name;
if ( w?$conn )
n$conn = w$conn;
else
{
if ( w?$uid )
n$uid = w$uid;
if ( w?$id )
n$id = w$id;
}
if ( w?$addl )
n$sub = w$addl;
NOTICE(n);
}
# This is for the temporary ignoring to reduce volume for identical weirds.
if ( name !in weird_do_not_ignore_repeats )
add weird_ignore[name, identifier];
Log::write(Weird::LOG, info);
if ( w$name !in weird_do_not_ignore_repeats )
add weird_ignore[w$name, identifier];
Log::write(Weird::LOG, w);
}
function report_conn(t: time, name: string, identifier: string, addl: string, c: connection)
{
local cid = c$id;
if ( [cid$orig_h, name] in ignore_hosts ||
[cid$resp_h, name] in ignore_hosts )
return;
current_conn = c;
report(t, name, identifier, T, addl);
}
function report_orig(t: time, name: string, identifier: string, orig: addr)
{
if ( [orig, name] in ignore_hosts )
return;
report(t, name, identifier, F, "");
}
# The following events come from core generated weirds typically.
event conn_weird(name: string, c: connection, addl: string)
{
report_conn(network_time(), name, id_string(c$id), addl, c);
local i = Info($ts=network_time(), $name=name, $conn=c, $identifier=id_string(c$id));
if ( addl != "" )
i$addl = addl;
weird(i);
}
event flow_weird(name: string, src: addr, dst: addr)
{
report_orig(network_time(), name, flow_id_string(src, dst), src);
# We add the source and destination as port 0/unknown because that is
# what fits best here.
local id = conn_id($orig_h=src, $orig_p=count_to_port(0, unknown_transport),
$resp_h=dst, $resp_p=count_to_port(0, unknown_transport));
local i = Info($ts=network_time(), $name=name, $id=id, $identifier=flow_id_string(src,dst));
weird(i);
}
event net_weird(name: string)
{
report(network_time(), name, "", F, "");
local i = Info($ts=network_time(), $name=name);
weird(i);
}

View file

@ -2,6 +2,7 @@
##! their responses.
@load base/utils/queue
@load base/frameworks/notice/weird
@load ./consts
module DNS;
@ -26,8 +27,8 @@ export {
## the DNS query. Also used in responses to match up replies to
## outstanding queries.
trans_id: count &log &optional;
## Round trip time for the query and response. This indicates
## the delay between when the request was seen until the
## Round trip time for the query and response. This indicates
## the delay between when the request was seen until the
## answer started.
rtt: interval &log &optional;
## The domain name that is the subject of the DNS query.
@ -103,7 +104,7 @@ export {
## when creating a new session value.
##
## c: The connection involved in the new session.
##
##
## msg: The DNS message header information.
##
## is_query: Indicator for if this is being called for a query or a response.
@ -176,8 +177,9 @@ function log_unmatched_msgs_queue(q: Queue::Queue)
for ( i in infos )
{
event flow_weird("dns_unmatched_msg",
infos[i]$id$orig_h, infos[i]$id$resp_h);
local wi = Weird::Info($ts=network_time(), $name="dns_unmatched_msg", $uid=infos[i]$uid,
$id=infos[i]$id);
Weird::weird(wi);
Log::write(DNS::LOG, infos[i]);
}
}
@ -192,12 +194,14 @@ function log_unmatched_msgs(msgs: PendingMessages)
function enqueue_new_msg(msgs: PendingMessages, id: count, msg: Info)
{
local wi: Weird::Info;
if ( id !in msgs )
{
if ( |msgs| > max_pending_query_ids )
{
event flow_weird("dns_unmatched_query_id_quantity",
msg$id$orig_h, msg$id$resp_h);
wi = Weird::Info($ts=network_time(), $name="dns_unmatched_msg", $uid=msg$uid,
$id=msg$id);
Weird::weird(wi);
# Throw away all unmatched on assumption they'll never be matched.
log_unmatched_msgs(msgs);
}
@ -208,8 +212,9 @@ function enqueue_new_msg(msgs: PendingMessages, id: count, msg: Info)
{
if ( Queue::len(msgs[id]) > max_pending_msgs )
{
event flow_weird("dns_unmatched_msg_quantity",
msg$id$orig_h, msg$id$resp_h);
wi = Weird::Info($ts=network_time(), $name="dns_unmatched_msg_quantity", $uid=msg$uid,
$id=msg$id);
Weird::weird(wi);
log_unmatched_msgs_queue(msgs[id]);
# Throw away all unmatched on assumption they'll never be matched.
msgs[id] = Queue::init();

View file

@ -3,101 +3,101 @@
#empty_field (empty)
#unset_field -
#path weird
#open 2013-08-26-19-02-06
#open 2016-06-15-20-38-04
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer
#types time string addr port addr port string string bool string
1332784981.078396 - - - - - bad_IP_checksum - F bro
#close 2013-08-26-19-02-06
#close 2016-06-15-20-38-04
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path weird
#open 2013-08-26-19-02-06
#open 2016-06-15-20-38-06
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer
#types time string addr port addr port string string bool string
1332784885.686428 CXWv6p3arKYeMETxOg 127.0.0.1 30000 127.0.0.1 80 bad_TCP_checksum - F bro
#close 2013-08-26-19-02-06
#close 2016-06-15-20-38-06
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path weird
#open 2013-08-26-19-02-07
#open 2016-06-15-20-38-08
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer
#types time string addr port addr port string string bool string
1332784933.501023 CXWv6p3arKYeMETxOg 127.0.0.1 30000 127.0.0.1 13000 bad_UDP_checksum - F bro
#close 2013-08-26-19-02-07
#close 2016-06-15-20-38-08
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path weird
#open 2013-08-26-19-02-07
#open 2016-06-15-20-38-10
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer
#types time string addr port addr port string string bool string
1334075363.536871 CXWv6p3arKYeMETxOg 192.168.1.100 8 192.168.1.101 0 bad_ICMP_checksum - F bro
#close 2013-08-26-19-02-07
#close 2016-06-15-20-38-10
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path weird
#open 2013-08-26-19-02-08
#open 2016-06-15-20-38-11
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer
#types time string addr port addr port string string bool string
1332785210.013051 - - - - - routing0_hdr - F bro
1332785210.013051 - 2001:4f8:4:7:2e0:81ff:fe52:ffff 0 2001:78:1:32::2 0 routing0_hdr - F bro
1332785210.013051 CXWv6p3arKYeMETxOg 2001:4f8:4:7:2e0:81ff:fe52:ffff 30000 2001:78:1:32::2 80 bad_TCP_checksum - F bro
#close 2013-08-26-19-02-08
#close 2016-06-15-20-38-12
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path weird
#open 2013-08-26-19-02-09
#open 2016-06-15-20-38-13
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer
#types time string addr port addr port string string bool string
1332782580.798420 - - - - - routing0_hdr - F bro
1332782580.798420 - 2001:4f8:4:7:2e0:81ff:fe52:ffff 0 2001:78:1:32::2 0 routing0_hdr - F bro
1332782580.798420 CXWv6p3arKYeMETxOg 2001:4f8:4:7:2e0:81ff:fe52:ffff 30000 2001:78:1:32::2 13000 bad_UDP_checksum - F bro
#close 2013-08-26-19-02-09
#close 2016-06-15-20-38-13
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path weird
#open 2013-08-26-19-02-09
#open 2016-06-15-20-38-15
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer
#types time string addr port addr port string string bool string
1334075111.800086 - - - - - routing0_hdr - F bro
1334075111.800086 - 2001:4f8:4:7:2e0:81ff:fe52:ffff 0 2001:78:1:32::1 0 routing0_hdr - F bro
1334075111.800086 CXWv6p3arKYeMETxOg 2001:4f8:4:7:2e0:81ff:fe52:ffff 128 2001:78:1:32::1 129 bad_ICMP_checksum - F bro
#close 2013-08-26-19-02-09
#close 2016-06-15-20-38-15
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path weird
#open 2013-08-26-19-02-10
#open 2016-06-15-20-38-16
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer
#types time string addr port addr port string string bool string
1332785250.469132 CXWv6p3arKYeMETxOg 2001:4f8:4:7:2e0:81ff:fe52:ffff 30000 2001:4f8:4:7:2e0:81ff:fe52:9a6b 80 bad_TCP_checksum - F bro
#close 2013-08-26-19-02-10
#close 2016-06-15-20-38-17
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path weird
#open 2013-08-26-19-02-10
#open 2016-06-15-20-38-18
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer
#types time string addr port addr port string string bool string
1332781342.923813 CXWv6p3arKYeMETxOg 2001:4f8:4:7:2e0:81ff:fe52:ffff 30000 2001:4f8:4:7:2e0:81ff:fe52:9a6b 13000 bad_UDP_checksum - F bro
#close 2013-08-26-19-02-10
#close 2016-06-15-20-38-18
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path weird
#open 2013-08-26-19-02-11
#open 2016-06-15-20-38-20
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer
#types time string addr port addr port string string bool string
1334074939.467194 CXWv6p3arKYeMETxOg 2001:4f8:4:7:2e0:81ff:fe52:ffff 128 2001:4f8:4:7:2e0:81ff:fe52:9a6b 129 bad_ICMP_checksum - F bro
#close 2013-08-26-19-02-11
#close 2016-06-15-20-38-20

View file

@ -3,68 +3,68 @@
#empty_field (empty)
#unset_field -
#path weird
#open 2013-08-26-19-34-56
#open 2016-06-15-20-38-20
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer
#types time string addr port addr port string string bool string
1334074939.467194 CXWv6p3arKYeMETxOg 2001:4f8:4:7:2e0:81ff:fe52:ffff 128 2001:4f8:4:7:2e0:81ff:fe52:9a6b 129 bad_ICMP_checksum - F bro
#close 2013-08-26-19-34-56
#close 2016-06-15-20-38-20
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path weird
#open 2013-08-26-19-34-57
#open 2016-06-15-20-38-27
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer
#types time string addr port addr port string string bool string
1332785125.596793 - - - - - routing0_hdr - F bro
#close 2013-08-26-19-34-57
1332785125.596793 - 2001:4f8:4:7:2e0:81ff:fe52:ffff 0 2001:78:1:32::2 0 routing0_hdr - F bro
#close 2016-06-15-20-38-27
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path weird
#open 2013-08-26-19-34-57
#open 2016-06-15-20-38-28
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer
#types time string addr port addr port string string bool string
1332782508.592037 - - - - - routing0_hdr - F bro
#close 2013-08-26-19-34-57
1332782508.592037 - 2001:4f8:4:7:2e0:81ff:fe52:ffff 0 2001:78:1:32::2 0 routing0_hdr - F bro
#close 2016-06-15-20-38-29
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path weird
#open 2013-08-26-19-34-57
#open 2016-06-15-20-38-30
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer
#types time string addr port addr port string string bool string
1334075027.053380 - - - - - routing0_hdr - F bro
#close 2013-08-26-19-34-57
1334075027.053380 - 2001:4f8:4:7:2e0:81ff:fe52:ffff 0 2001:78:1:32::1 0 routing0_hdr - F bro
#close 2016-06-15-20-38-30
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path weird
#open 2013-08-26-19-34-57
#open 2016-06-15-20-38-30
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer
#types time string addr port addr port string string bool string
1334075027.053380 - - - - - routing0_hdr - F bro
#close 2013-08-26-19-34-57
1334075027.053380 - 2001:4f8:4:7:2e0:81ff:fe52:ffff 0 2001:78:1:32::1 0 routing0_hdr - F bro
#close 2016-06-15-20-38-30
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path weird
#open 2013-08-26-19-34-57
#open 2016-06-15-20-38-30
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer
#types time string addr port addr port string string bool string
1334075027.053380 - - - - - routing0_hdr - F bro
#close 2013-08-26-19-34-57
1334075027.053380 - 2001:4f8:4:7:2e0:81ff:fe52:ffff 0 2001:78:1:32::1 0 routing0_hdr - F bro
#close 2016-06-15-20-38-30
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path weird
#open 2013-08-26-19-34-57
#open 2016-06-15-20-38-30
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer
#types time string addr port addr port string string bool string
1334075027.053380 - - - - - routing0_hdr - F bro
#close 2013-08-26-19-34-57
1334075027.053380 - 2001:4f8:4:7:2e0:81ff:fe52:ffff 0 2001:78:1:32::1 0 routing0_hdr - F bro
#close 2016-06-15-20-38-30

View file

@ -3,7 +3,6 @@ flow weird, excessively_small_fragment, 164.1.123.163, 164.1.123.61
flow weird, fragment_size_inconsistency, 164.1.123.163, 164.1.123.61
flow weird, fragment_inconsistency, 164.1.123.163, 164.1.123.61
flow weird, fragment_inconsistency, 164.1.123.163, 164.1.123.61
flow weird, dns_unmatched_msg, 164.1.123.163, 164.1.123.61
----------------------
flow weird, excessively_small_fragment, 164.1.123.163, 164.1.123.61
flow weird, excessively_small_fragment, 164.1.123.163, 164.1.123.61

View file

@ -3,10 +3,10 @@
#empty_field (empty)
#unset_field -
#path weird
#open 2015-03-19-15-44-23
#open 2016-06-15-20-29-41
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer
#types time string addr port addr port string string bool string
1363716396.798286 CXWv6p3arKYeMETxOg 55.247.223.174 27285 222.195.43.124 53 DNS_RR_unknown_type 46 F bro
1363716396.798374 CXWv6p3arKYeMETxOg 55.247.223.174 27285 222.195.43.124 53 dns_unmatched_reply - F bro
1363716396.798374 - - - - - dns_unmatched_msg - F bro
#close 2015-03-19-15-44-23
1363716396.798374 CXWv6p3arKYeMETxOg 55.247.223.174 27285 222.195.43.124 53 dns_unmatched_msg - F bro
#close 2016-06-15-20-29-41