Enhance ssl.log with information from notary.

This commit brings enhances each log line with the data from the notary when
available. The added fields include:

  - notary.first_seen
  - notary.last_seen
  - notary.times_seen
  - notary.valid

The semantics of these fields map 1-to-1 to the corresponding fields in DNS TXT
lookups from the notary. The implementation of this feature required a bit
plumbing: when Bro finishes the analysis, the log record is copied into table
indexed by connection ID where it remains until either Bro terminates or the
answer of the notary arrives. The script accummulates requests for a given
digest into a "waitlist," to avoid multiple redundant lookups for high-profile
websites who receive a large chunk of traffic. When a DNS reply arrives
asynchronously, the when handler clears the waitlist and assigns the
information to all records in the buffered.

The script also adds Each log entry into a double-ended queue to make sure the
records arrive on disk in the same way Bro sees them. Each reply also triggers
a sweep through this deque which flushes the buffer up to the first outstanding
reply.

Here is an example from the public M57 trace from 2009:

  % bro-cut ts id.orig_h id.resp_h server_name notary.first_seen notary.last_seen notary.times_seen notary.valid < ssl.log
  1258562650.121682 192.168.1.104 208.97.132.223  mail.m57.biz  - - - -
  1258535660.267128 192.168.1.104 65.55.184.16  - - - - -
  1258561662.604948 192.168.1.105 66.235.128.158  - - - - -
  1258561885.571010 192.168.1.105 65.55.184.155 www.update.microsoft.com  - - - -
  1258563578.455331 192.168.1.103 208.97.132.223  - - - - -
  1258563716.527681 192.168.1.103 96.6.248.124  - - - - -
  1258563884.667153 192.168.1.103 66.235.139.152  - - - - -
  1258564818.755676 192.168.1.103 12.41.118.177 - - - - -
  1258564821.637874 192.168.1.103 12.41.118.177 - - - - -
  1258564821.637871 192.168.1.103 12.41.118.177 - - - - -
  1258564821.637876 192.168.1.103 12.41.118.177 - - - - -
  1258564821.638126 192.168.1.103 12.41.118.177 - - - - -
  1258562467.525034 192.168.1.104 208.97.132.223  mail.m57.biz  15392 15695 301 F
  1258563063.965975 192.168.1.104 63.245.209.105  aus2.mozilla.org  - - - -
  1258563064.091396 192.168.1.104 63.245.209.91 addons.mozilla.org  - - - -
  1258563329.202273 192.168.1.103 208.97.132.223  - 15392 15695 301 F
  1258563712.945933 192.168.1.103 65.55.16.121  - - - - -
  1258563714.044500 192.168.1.103 65.54.186.79  - - - - -
  1258563716.146680 192.168.1.103 96.6.248.124  - - - - -
  1258563737.432312 192.168.1.103 96.6.245.186  - - - - -
  1258563716.526933 192.168.1.103 96.6.245.186  - - - - -
  1258563716.527430 192.168.1.103 96.6.245.186  - - - - -
  1258563716.527179 192.168.1.103 96.6.245.186  - - - - -
  1258563716.527683 192.168.1.103 96.6.245.186  - - - - -
  1258563716.527432 192.168.1.103 96.6.245.186  - - - - -
  1258563751.178683 192.168.1.103 66.235.139.152  - - - - -
  1258563751.171938 192.168.1.103 65.54.234.75  - - - - -
  1258563751.182433 192.168.1.103 65.242.27.35  - - - - -
  1258563883.414188 192.168.1.103 65.55.16.121  - - - - -
  1258563884.702380 192.168.1.103 65.242.27.35  - - - - -
  1258563885.678766 192.168.1.103 65.54.186.79  - - - - -
  1258563886.124987 192.168.1.103 65.54.186.79  - - - - -
  1258564027.877525 192.168.1.103 65.54.234.75  - - - - -
  1258564688.206859 192.168.1.103 65.54.186.107 - - - - -
  1258567162.001225 192.168.1.105 208.97.132.223  mail.m57.biz  - - - -
  1258568040.512840 192.168.1.103 208.97.132.223  - - - - -
  1258564688.577376 192.168.1.103 207.46.120.170  - - - - -
  1258564723.029005 192.168.1.103 65.54.186.107 - - - - -
  1258564723.784032 192.168.1.103 65.55.194.249 - - - - -
  1258564748.521756 192.168.1.103 65.54.186.107 - - - - -
  1258564817.601152 192.168.1.103 12.41.118.177 - - - - -
  1258565684.353653 192.168.1.105 208.97.132.223  mail.m57.biz  15392 15695 301 F
  1258565710.188691 192.168.1.105 74.125.155.109  pop.gmail.com - - - -
  1258566061.103696 192.168.1.103 208.97.132.223  - 15392 15695 301 F
  1258566893.914987 192.168.1.102 208.97.132.223  - 15392 15695 301 F
This commit is contained in:
Matthias Vallentin 2012-12-21 17:03:39 -08:00
parent 5526f09b60
commit ff8184242a

View file

@ -8,6 +8,14 @@ module SSL;
export {
redef enum Log::ID += { LOG };
## A response from the ICSI certificate notary.
type NotaryResponse: record {
first_seen: count &log &optional;
last_seen: count &log &optional;
times_seen: count &log &optional;
valid: bool &log &optional;
};
type Info: record {
## Time when the SSL connection was first detected.
ts: time &log;
@ -72,15 +80,48 @@ export {
## utility.
const openssl_util = "openssl" &redef;
## Flag that determines whether to use the ICSI certificate notary to enhance
## the SSL log records.
const use_notary = T &redef;
## Event that can be handled to access the SSL
## record as it is sent on to the logging framework.
global log_ssl: event(rec: Info);
}
# TODO: Maybe wrap these in @ifdef's? Otherwise we carry the extra baggage
# around all the time.
redef record Info += {
sha1_digest: string &optional;
notary: NotaryResponse &log &optional;
};
redef record connection += {
ssl: Info &optional;
};
# The DNS cache of notary responses.
global notary_cache: table[string] of NotaryResponse &create_expire = 1 hr;
# The buffered SSL log records.
global records: table[string] of Info;
# 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
# reply arrives asynchronously.
global waiting: table[string] of vector of string;
# A double-ended queue that determines the log record order in which logs have
# to written out to disk.
global deque: table[count] of string;
# The top-most deque index.
global head = 0;
# The bottom deque index that points to the next record to be flushed as soon
# as the notary response arrives.
global tail = 0;
event bro_init() &priority=5
{
Log::create_stream(SSL::LOG, [$columns=Info, $ev=log_ssl]);
@ -122,9 +163,103 @@ function set_session(c: connection)
$client_cert_chain=vector()];
}
function clear_waitlist(digest: string)
{
if ( digest in waiting )
{
for ( i in waiting[digest] )
{
local uid = waiting[digest][i];
records[uid]$notary = [];
}
delete waiting[digest];
}
}
function lookup_cert_hash(uid: string, digest: string)
{
# Add the record ID to the list of waiting IDs for this digest.
local waits_already = digest in waiting;
if ( ! waits_already )
waiting[digest] = vector();
waiting[digest][|waiting[digest]|] = uid;
if ( waits_already )
return;
local domain = "%s.notary.icsi.berkeley.edu";
when ( local str = lookup_hostname_txt(fmt(domain, digest)) )
{
# Cache every response for a digest.
# TODO: should we ignore failing answers?
notary_cache[digest] = [];
# Parse notary answer.
if ( str == "<???>" )
{
# TODO: Should we handle NXDOMAIN separately?
clear_waitlist(digest);
return;
}
local fields = split(str, / /);
if ( |fields| != 5 ) # version 1 has 5 fields.
{
clear_waitlist(digest);
return;
}
local version = split(fields[1], /=/)[2];
if ( version != "1" )
{
clear_waitlist(digest);
return;
}
local r = notary_cache[digest];
r$first_seen = to_count(split(fields[2], /=/)[2]);
r$last_seen = to_count(split(fields[3], /=/)[2]);
r$times_seen = to_count(split(fields[4], /=/)[2]);
r$valid = split(fields[5], /=/)[2] == "1";
# Assign notary answer to all waiting records.
if ( digest in waiting )
{
for ( i in waiting[digest] )
records[waiting[digest][i]]$notary = r;
delete waiting[digest];
}
# Flush all records up to the record which still awaits an answer.
local current: string;
for ( unused_index in deque )
{
current = deque[tail];
local info = records[current];
if ( ! info?$notary )
break;
Log::write(SSL::LOG, info);
delete deque[tail];
delete records[current];
++tail;
}
}
}
function finish(c: connection)
{
if ( use_notary && c$ssl?$sha1_digest)
{
local digest = c$ssl$sha1_digest;
if ( c$ssl$sha1_digest in notary_cache )
c$ssl$notary = notary_cache[digest];
else
lookup_cert_hash(c$uid, digest);
records[c$uid] = c$ssl; # Copy the record.
deque[head] = c$uid;
++head;
}
else
{
Log::write(SSL::LOG, c$ssl);
}
if ( disable_analyzer_after_detection && c?$ssl && c$ssl?$analyzer_id )
disable_analyzer(c$id, c$ssl$analyzer_id);
delete c$ssl;
@ -181,6 +316,9 @@ event x509_certificate(c: connection, is_orig: bool, cert: X509, chain_idx: coun
c$ssl$issuer_subject = cert$issuer;
c$ssl$not_valid_before = cert$not_valid_before;
c$ssl$not_valid_after = cert$not_valid_after;
if ( use_notary )
c$ssl$sha1_digest = sha1_hash(der_cert);
}
else
{
@ -228,3 +366,20 @@ event protocol_violation(c: connection, atype: count, aid: count,
if ( c?$ssl )
finish(c);
}
event bro_done()
{
if ( ! use_notary || |deque| == 0 )
return;
local current: string;
for ( unused_index in deque )
{
current = deque[tail];
local info = records[current];
Log::write(SSL::LOG, info);
delete deque[tail];
delete records[current];
++tail;
}
}