Implement delay-token style SSL logging.

This commit moves the notary script into the policy directory, along with some
architectural changes: the main SSL script now has functionality to add and
remove tokens for a given record. When adding a token, the script delays the
logging until the token has been removed or until the record exceeds a maximum
delay time.

As before, the base SSL script stores all records sequentially and buffers even
non-delayed records for the sake of having an ordered log file. If this turns
out to be not so important, we can easily revert to a simpler logic.

(This is still WiP, some debuggin statements still linger.)

scripts/base/protocols/ssl/__load__.bro

@@ -1,65 +1,3 @@
 @load ./consts
-
-module SSL;
-
-export {
-	redef enum Log::ID += { LOG };
-
-	type Info: record {
-		## Time when the SSL connection was first detected.
-		ts:               time             &log;
-		## Unique ID for the connection.
-		uid:         string          &log;
-		## The connection's 4-tuple of endpoint addresses/ports.
-		id:               conn_id          &log;
-		## SSL/TLS version that the server offered.
-		version:          string           &log &optional;
-		## SSL/TLS cipher suite that the server chose.
-		cipher:           string           &log &optional;
-		## Value of the Server Name Indicator SSL/TLS extension.  It
-		## indicates the server name that the client was requesting.
-		server_name:      string           &log &optional;
-		## Session ID offered by the client for session resumption.
-		session_id:       string           &log &optional;
-		## Subject of the X.509 certificate offered by the server.
-		subject:          string           &log &optional;
-		## Subject of the signer of the X.509 certificate offered by the server.
-		issuer_subject:   string           &log &optional;
-		## NotValidBefore field value from the server certificate.
-		not_valid_before: time             &log &optional;
-		## NotValidAfter field value from the server certificate.
-		not_valid_after:  time             &log &optional;
-		## Last alert that was seen during the connection.
-		last_alert:       string           &log &optional;
-
-		## Subject of the X.509 certificate offered by the client.
-		client_subject:          string           &log &optional;
-		## Subject of the signer of the X.509 certificate offered by the client.
-		client_issuer_subject:   string           &log &optional;
-
-		## Full binary server certificate stored in DER format.
-		cert:             string           &optional;
-		## Chain of certificates offered by the server to validate its
-		## complete signing chain.
-		cert_chain:       vector of string &optional;
-
-		## Full binary client certificate stored in DER format.
-		client_cert:             string           &optional;
-		## Chain of certificates offered by the client to validate its
-		## complete signing chain.
-		client_cert_chain:       vector of string &optional;
-
-		## The analyzer ID used for the analyzer instance attached
-		## to each connection.  It is not used for logging since it's a
-		## meaningless arbitrary number.
-		analyzer_id:      count            &optional;
-	};
-}
-
-redef record connection += {
-	ssl: Info &optional;
-};
-
-@load ./notary
 @load ./main
 @load ./mozilla-ca-list

scripts/base/protocols/ssl/main.bro

@@ -6,6 +6,63 @@
 module SSL;
 
 export {
+	redef enum Log::ID += { LOG };
+
+	type Info: record {
+		## Time when the SSL connection was first detected.
+		ts:               time             &log;
+		## Unique ID for the connection.
+		uid:         string          &log;
+		## The connection's 4-tuple of endpoint addresses/ports.
+		id:               conn_id          &log;
+		## SSL/TLS version that the server offered.
+		version:          string           &log &optional;
+		## SSL/TLS cipher suite that the server chose.
+		cipher:           string           &log &optional;
+		## Value of the Server Name Indicator SSL/TLS extension.  It
+		## indicates the server name that the client was requesting.
+		server_name:      string           &log &optional;
+		## Session ID offered by the client for session resumption.
+		session_id:       string           &log &optional;
+		## Subject of the X.509 certificate offered by the server.
+		subject:          string           &log &optional;
+		## Subject of the signer of the X.509 certificate offered by the server.
+		issuer_subject:   string           &log &optional;
+		## NotValidBefore field value from the server certificate.
+		not_valid_before: time             &log &optional;
+		## NotValidAfter field value from the server certificate.
+		not_valid_after:  time             &log &optional;
+		## Last alert that was seen during the connection.
+		last_alert:       string           &log &optional;
+
+		## Subject of the X.509 certificate offered by the client.
+		client_subject:          string           &log &optional;
+		## Subject of the signer of the X.509 certificate offered by the client.
+		client_issuer_subject:   string           &log &optional;
+
+		## Full binary server certificate stored in DER format.
+		cert:             string           &optional;
+		## Chain of certificates offered by the server to validate its
+		## complete signing chain.
+		cert_chain:       vector of string &optional;
+
+		## Full binary client certificate stored in DER format.
+		client_cert:             string           &optional;
+		## Chain of certificates offered by the client to validate its
+		## complete signing chain.
+		client_cert_chain:       vector of string &optional;
+
+		## The analyzer ID used for the analyzer instance attached
+		## to each connection.  It is not used for logging since it's a
+		## meaningless arbitrary number.
+		analyzer_id:      count            &optional;
+
+		## Adding a string "token" to this set will cause the SSL script
+    ## to delay logging the record until either the token has been removed or
+    ## the record has been delayed for :bro:id:`SSL::max_log_delay`.
+	  delay_tokens: set[string] &optional;	
+	};
+
 	## The default root CA bundle.  By loading the
 	## mozilla-ca-list.bro script it will be set to Mozilla's root CA list.
 	const root_certs: table[string] of string = {} &redef;
@@ -20,11 +77,24 @@ export {
 	## utility.
 	const openssl_util = "openssl" &redef;
 
+	## The maximum amount of time a plugin can delay records from being logged.
+	const max_log_delay = 15secs &redef;
+
+	## TODO: document.
+	global add_delayed_record: function(info: Info, token: string);
+
+	## TODO: document.
+	global clear_delayed_record: function(uid: string, token: string) : Info;
+
 	## 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);
 }
 
+redef record connection += {
+	ssl: Info &optional;
+};
+
 event bro_init() &priority=5
 	{
 	Log::create_stream(SSL::LOG, [$columns=Info, $ev=log_ssl]);
@@ -59,6 +129,20 @@ redef likely_server_ports += {
 	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
+# 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;
+
 function set_session(c: connection)
 	{
 	if ( ! c?$ssl )
@@ -66,16 +150,69 @@ function set_session(c: connection)
 		         $client_cert_chain=vector()];
 	}
 
+function add_delayed_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();
+	add info$delay_tokens[token];
+	}
+
+function clear_delayed_record(uid: string, token: string) : Info
+	{
+	local info = records[uid];
+	delete info$delay_tokens[token];
+	return info;
+	}
+
+global log_record: function(info: Info);
+
+event delay_logging(info: Info)
+	{
+	log_record(info);
+	}
+
+function log_record(info: Info)
+	{
+	for ( unused_index in records )
+		{
+		if ( head == tail )
+			return;
+		local uid = deque[tail];
+		if ( |records[uid]$delay_tokens| > 0 )
+			{
+			if ( info$ts + max_log_delay > network_time() )
+				{
+				schedule 1sec { delay_logging(info) };
+				return;
+				}
+			else
+				{
+				event reporter_info(
+						network_time(),
+						fmt("SSL delay tokens not released in time (%s)",
+								info$delay_tokens),
+						"");
+				}
+			}
+		Log::write(SSL::LOG, records[uid]);
+		delete records[uid];
+		delete deque[tail];
+		++tail;
+		}
+	}
+
 function finish(c: connection)
 	{
-# TODO: This dummy flag merely exists to check whether the notary script is
+	log_record(c$ssl);
-# loaded. There's probably a better way to incorporate the notary.
-@ifdef( Notary::enabled )
-	Notary::push(c$ssl);
-@else
-	Log::write(SSL::LOG, c$ssl);
-@endif
-
 	if ( disable_analyzer_after_detection && c?$ssl && c$ssl?$analyzer_id )
 		disable_analyzer(c$id, c$ssl$analyzer_id);
 	delete c$ssl;
@@ -179,3 +316,17 @@ event protocol_violation(c: connection, atype: count, aid: count,
 	if ( c?$ssl )
 		finish(c);
 	}
+
+event bro_done()
+	{
+	if ( |records| == 0 )
+		return;
+	for ( unused_index in records )
+		{
+		local uid = deque[tail];
+		Log::write(SSL::LOG, records[uid]);
+		delete records[uid];
+		delete deque[tail];
+		++tail;
+		}
+	}

scripts/policy/protocols/ssl/notary.bro

@@ -1,10 +1,6 @@
 module Notary;
 
 export {
-	# Flag to tell the SSL analysis script that it should buffer logs instead of
-	# flushing them directly.
-	const enabled = T;
-
 	## A response from the ICSI certificate notary.
 	type Response: record {
 		first_seen: count &log &optional;
@@ -13,83 +9,66 @@ export {
 		valid: bool &log &optional;
 	};
 
-	## Hands over an SSL record to the Notary module. This is an ownership
-	## transfer, i.e., the caller does not need to call Log::write on this record
-	## anymore.
-	global push: function(info: SSL::Info);
-
 	## The notary domain to query.
 	const domain = "notary.icsi.berkeley.edu" &redef;
 }
 
 redef record SSL::Info += {
-	sha1_digest: string &optional;
+	sha1: string &log &optional;
 	notary: Response &log &optional;
 	};
 
 # The DNS cache of notary responses.
 global notary_cache: table[string] of Response &create_expire = 1 hr;
 
-# The buffered SSL log records.
-global records: table[string] of SSL::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;
-
 function clear_waitlist(digest: string)
 	{
+	print "----- clearing waitlist -----";
 	if ( digest in waiting )
 		{
 		for ( i in waiting[digest] )
 			{
-			local uid = waiting[digest][i];
+      print fmt("----- retrieving %s -----", waiting[digest][i]);
-			records[uid]$notary = [];
+			local info = SSL::clear_delayed_record(waiting[digest][i], "notary");
+			info$notary = [];
 			}
 		delete waiting[digest];
 		}
 	}
 
-function flush(evict_all: bool)
+event x509_certificate(c: connection, is_orig: bool, cert: X509,
+    chain_idx: count, chain_len: count, der_cert: string)
 	{
-	local current: string;
+	if ( is_orig || chain_idx != 0 || ! c?$ssl )
-	for ( unused_index in deque )
+	  return;
-		{
-		current = deque[tail];
-		local info = records[current];
-		if ( ! evict_all && ! info?$notary )
-			break;
-		Log::write(SSL::LOG, info);
-		delete deque[tail];
-		delete records[current];
-		++tail;
-		}
-	}
 
-function lookup_cert_hash(uid: string, digest: string)
+  local digest = sha1_hash(der_cert);
-	j{
+	c$ssl$sha1 = digest;
-	j# Add the record ID to the list of waiting IDs for this digest.
+
-	jlocal waits_already = digest in waiting;
+	if ( digest in notary_cache )
-	jif ( ! waits_already )
+    {
+		c$ssl$notary = notary_cache[digest];
+		return;
+		}
+
+  print fmt("----- adding %s -----", c$ssl$uid);
+  SSL::add_delayed_record(c$ssl, "notary");
+
+	local waits_already = digest in waiting;
+	if ( ! waits_already )
 		waiting[digest] = vector();
-	waiting[digest][|waiting[digest]|] = uid;
+	waiting[digest][|waiting[digest]|] = c$uid;
 	if ( waits_already )
 		return;
 
 	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] = [];
 
@@ -122,41 +101,11 @@ function lookup_cert_hash(uid: string, digest: string)
 		if ( digest in waiting )
 			{
 			for ( i in waiting[digest] )
-				records[waiting[digest][i]]$notary = r;
+			{
+			  local info = SSL::clear_delayed_record(waiting[digest][i], "notary");
+				info$notary = r;
+      }
 			delete waiting[digest];
 			}
-
-		flush(F);
 		}
 	}
-
-function push(info: SSL::Info)
-	{
-	if ( ! info?$sha1_digest )
-	  return;
-
-	local digest = info$sha1_digest;
-	if ( info$sha1_digest in notary_cache )
-		info$notary = notary_cache[digest];
-	else
-		lookup_cert_hash(info$uid, digest);
-	records[info$uid] = info;
-	deque[head] = info$uid;
-	++head;
-	}
-
-event x509_certificate(c: connection, is_orig: bool, cert: X509,
-    chain_idx: count, chain_len: count, der_cert: string)
-	{
-	if ( is_orig || chain_idx != 0 || ! c?$ssl )
-	  return;
-
-	c$ssl$sha1_digest = sha1_hash(der_cert);
-	}
-
-event bro_done()
-	{
-	if ( |deque| == 0 )
-		return;
-	flush(T);
-	}

scripts/site/local.bro

@@ -56,6 +56,10 @@ redef Software::vulnerable_versions += {
 # This script enables SSL/TLS certificate validation.
 @load protocols/ssl/validate-certs
 
+# This script checks each SSL certificate hash against the ICSI certificate
+# notary service.
+@load protocols/ssl/notary
+
 # If you have libGeoIP support built in, do some geographic detections and 
 # logging for SSH traffic.
 @load protocols/ssh/geo-data