Simplify delayed logging of SSL records.

This commit is contained in:
Matthias Vallentin 2012-12-24 22:57:15 -08:00
parent 9e81342c92
commit 7ff15f4599
2 changed files with 39 additions and 61 deletions

View file

@ -80,11 +80,13 @@ export {
## The maximum amount of time a plugin can delay records from being logged. ## The maximum amount of time a plugin can delay records from being logged.
const max_log_delay = 15secs &redef; const max_log_delay = 15secs &redef;
## TODO: document. ## Delays an SSL record for a specific token: the record will not be logged
global add_delayed_record: function(info: Info, token: string); ## as longs the token exists or until :bro:id:`SSL::max_log_delay` elapses.
global delay_record: function(info: Info, token: string);
## TODO: document. ## Undelays an SSL record for a previously inserted token, allowing the
global clear_delayed_record: function(uid: string, token: string) : Info; ## record to be logged.
global undelay_record: function(info: Info, token: string);
## Event that can be handled to access the SSL ## Event that can be handled to access the SSL
## record as it is sent on to the logging framework. ## record as it is sent on to the logging framework.
@ -129,12 +131,9 @@ redef likely_server_ports += {
989/tcp, 990/tcp, 992/tcp, 993/tcp, 995/tcp, 5223/tcp 989/tcp, 990/tcp, 992/tcp, 993/tcp, 995/tcp, 5223/tcp
}; };
# The buffered SSL log records.
global records: table[string] of Info;
# A double-ended queue that determines the log record order in which logs have # A double-ended queue that determines the log record order in which logs have
# to written out to disk. # to written out to disk.
global deque: table[count] of string; global deque: table[count] of Info;
# The top-most deque index. # The top-most deque index.
global head = 0; global head = 0;
@ -150,27 +149,19 @@ function set_session(c: connection)
$client_cert_chain=vector()]; $client_cert_chain=vector()];
} }
function add_delayed_record(info: Info, token: string) function delay_record(info: Info, token: string)
{ {
if ( info$uid in records )
{
print fmt("----- ignoring duplicate %s -----", info$uid);
return;
}
records[info$uid] = info;
deque[head] = info$uid;
++head;
info$delay_tokens = set(); info$delay_tokens = set();
add info$delay_tokens[token]; add info$delay_tokens[token];
deque[head] = info;
++head;
} }
function clear_delayed_record(uid: string, token: string) : Info function undelay_record(info: Info, token: string)
{ {
local info = records[uid]; if ( token in info$delay_tokens )
delete info$delay_tokens[token]; delete info$delay_tokens[token];
return info;
} }
global log_record: function(info: Info); global log_record: function(info: Info);
@ -182,12 +173,11 @@ event delay_logging(info: Info)
function log_record(info: Info) function log_record(info: Info)
{ {
for ( unused_index in records ) for ( unused_index in deque )
{ {
if ( head == tail ) if ( head == tail )
return; return;
local uid = deque[tail]; if ( |deque[tail]$delay_tokens| > 0 )
if ( |records[uid]$delay_tokens| > 0 )
{ {
if ( info$ts + max_log_delay > network_time() ) if ( info$ts + max_log_delay > network_time() )
{ {
@ -203,8 +193,7 @@ function log_record(info: Info)
""); "");
} }
} }
Log::write(SSL::LOG, records[uid]); Log::write(SSL::LOG, deque[tail]);
delete records[uid];
delete deque[tail]; delete deque[tail];
++tail; ++tail;
} }
@ -215,7 +204,6 @@ function finish(c: connection)
log_record(c$ssl); log_record(c$ssl);
if ( disable_analyzer_after_detection && c?$ssl && c$ssl?$analyzer_id ) if ( disable_analyzer_after_detection && c?$ssl && c$ssl?$analyzer_id )
disable_analyzer(c$id, c$ssl$analyzer_id); disable_analyzer(c$id, c$ssl$analyzer_id);
delete c$ssl;
} }
event ssl_client_hello(c: connection, version: count, possible_ts: time, session_id: string, ciphers: count_set) &priority=5 event ssl_client_hello(c: connection, version: count, possible_ts: time, session_id: string, ciphers: count_set) &priority=5
@ -319,13 +307,11 @@ event protocol_violation(c: connection, atype: count, aid: count,
event bro_done() event bro_done()
{ {
if ( |records| == 0 ) if ( |deque| == 0 )
return; return;
for ( unused_index in records ) for ( unused_index in deque )
{ {
local uid = deque[tail]; Log::write(SSL::LOG, deque[tail]);
Log::write(SSL::LOG, records[uid]);
delete records[uid];
delete deque[tail]; delete deque[tail];
++tail; ++tail;
} }

View file

@ -24,20 +24,15 @@ global notary_cache: table[string] of Response &create_expire = 1 hr;
# The records that wait for a notary response identified by the cert digest. # The records that wait for a notary response identified by the cert digest.
# Each digest refers to a list of connection UIDs which are updated when a DNS # Each digest refers to a list of connection UIDs which are updated when a DNS
# reply arrives asynchronously. # reply arrives asynchronously.
global waiting: table[string] of vector of string; global wait_list: table[string] of vector of SSL::Info;
function clear_waitlist(digest: string) function clear_waitlist(digest: string)
{ {
print "----- clearing waitlist -----"; if ( digest in wait_list )
if ( digest in waiting )
{ {
for ( i in waiting[digest] ) for ( i in wait_list[digest] )
{ SSL::undelay_record(wait_list[digest][i], "notary");
print fmt("----- retrieving %s -----", waiting[digest][i]); delete wait_list[digest];
local info = SSL::clear_delayed_record(waiting[digest][i], "notary");
info$notary = [];
}
delete waiting[digest];
} }
} }
@ -56,26 +51,22 @@ event x509_certificate(c: connection, is_orig: bool, cert: X509,
return; return;
} }
print fmt("----- adding %s -----", c$ssl$uid); SSL::delay_record(c$ssl, "notary");
SSL::add_delayed_record(c$ssl, "notary");
local waits_already = digest in waiting; local waits_already = digest in wait_list;
if ( ! waits_already ) if ( ! waits_already )
waiting[digest] = vector(); wait_list[digest] = vector();
waiting[digest][|waiting[digest]|] = c$uid; wait_list[digest][|wait_list[digest]|] = c$ssl;
if ( waits_already ) if ( waits_already )
return; return;
when ( local str = lookup_hostname_txt(fmt("%s.%s", digest, domain)) ) when ( local str = lookup_hostname_txt(fmt("%s.%s", digest, domain)) )
{ {
print fmt("----- when for %s: %s -----", digest, str);
# Cache every response for a digest.
notary_cache[digest] = []; notary_cache[digest] = [];
# Parse notary answer. # Parse notary answer.
if ( str == "<???>" ) if ( str == "<???>" ) # NXDOMAIN
{ {
# TODO: Should we handle NXDOMAIN separately?
clear_waitlist(digest); clear_waitlist(digest);
return; return;
} }
@ -97,15 +88,16 @@ event x509_certificate(c: connection, is_orig: bool, cert: X509,
r$times_seen = to_count(split(fields[4], /=/)[2]); r$times_seen = to_count(split(fields[4], /=/)[2]);
r$valid = split(fields[5], /=/)[2] == "1"; r$valid = split(fields[5], /=/)[2] == "1";
# Assign notary answer to all waiting records. # Assign notary answer to all records waiting for this digest.
if ( digest in waiting ) if ( digest in wait_list )
{ {
for ( i in waiting[digest] ) for ( i in wait_list[digest] )
{ {
local info = SSL::clear_delayed_record(waiting[digest][i], "notary"); local info = wait_list[digest][i];
SSL::undelay_record(info, "notary");
info$notary = r; info$notary = r;
} }
delete waiting[digest]; delete wait_list[digest];
} }
} }
} }