Merge branch 'topic/seth/krb5-ticket-tracking-merge'

* topic/seth/krb5-ticket-tracking-merge:
  Refactor base krb scripts and update tests.
  Add script to log ticket hashes in krb log
  Ensure TGS req does not stomp out AP data
  Add ciphertext to ticket data structures

CHANGES

@@ -1,4 +1,12 @@
 
+2.5-68 | 2017-02-18 13:59:05 -0500
+
+  * Refactored base krb scripts. (Seth Hall)
+
+  * New script to log ticket hashes in krb log 
+    (policy/protocols/krb/ticket-logging.bro).  Also, add 
+    ciphertext to ticket data structure. (John E. Rollinson)
+
 2.5-62 | 2017-02-15 15:56:38 -0800
 
   * Fix case in which scripts were able to access unitialized variables

VERSION

@@ -1 +1 @@
-2.5-62
+2.5-68

scripts/base/init-bare.bro

@@ -3955,6 +3955,8 @@ export {
 		service_name	: string;
 		## Cipher the ticket was encrypted with
 		cipher		: count;
+		## Cipher text of the ticket
+		ciphertext  : string &optional;
 	};
 
 	type KRB::Ticket_Vector: vector of KRB::Ticket;

scripts/base/protocols/krb/files.bro

@@ -78,30 +78,19 @@ event file_over_new_connection(f: fa_file, c: connection, is_orig: bool) &priori
 	if ( f$source != "KRB_TCP" && f$source != "KRB" )
 		return;
 
-	local info: Info;
+	set_session(c);
-
-	if ( ! c?$krb )
-		{
-		info$ts  = network_time();
-		info$uid = c$uid;
-		info$id  = c$id;
-		}
-	else
-		info = c$krb;
 
 	if ( is_orig )
 		{
-		info$client_cert = f$info;
+		c$krb$client_cert = f$info;
-		info$client_cert_fuid = f$id;
+		c$krb$client_cert_fuid = f$id;
 		}
 	else
 		{
-		info$server_cert = f$info;
+		c$krb$server_cert = f$info;
-		info$server_cert_fuid = f$id;
+		c$krb$server_cert_fuid = f$id;
 		}
 
-	c$krb = info;
-
 	Files::add_analyzer(f, Files::ANALYZER_X509);
 	# Always calculate hashes. They are not necessary for base scripts
 	# but very useful for identification, and required for policy scripts
@@ -111,7 +100,7 @@ event file_over_new_connection(f: fa_file, c: connection, is_orig: bool) &priori
 
 function fill_in_subjects(c: connection)
 	{
-	if ( !c?$krb )
+	if ( ! c?$krb )
 		return;
 
 	if ( c$krb?$client_cert && c$krb$client_cert?$x509 && c$krb$client_cert$x509?$certificate )

scripts/base/protocols/krb/main.bro

@@ -22,7 +22,7 @@ export {
 		## Client
 		client:        string   &log &optional;
 		## Service
-		service:		string &log;
+		service:       string   &log &optional;
 
 		## Request result
 		success:       bool     &log &optional;
@@ -80,172 +80,140 @@ event bro_init() &priority=5
 	Log::create_stream(KRB::LOG, [$columns=Info, $ev=log_krb, $path="kerberos"]);
 	}
 
+function set_session(c: connection): bool
+	{
+	if ( ! c?$krb )
+		{
+		c$krb = Info($ts  = network_time(),
+		             $uid = c$uid,
+		             $id  = c$id);
+		}
+	
+	return c$krb$logged;
+	}
+
+function do_log(c: connection)
+	{
+	if ( c?$krb && ! c$krb$logged )
+		{
+		Log::write(KRB::LOG, c$krb);
+		c$krb$logged = T;
+		}
+	}
+
 event krb_error(c: connection, msg: Error_Msg) &priority=5
 	{
-	local info: Info;
+	if ( set_session(c) )
+		return;
 
 	if ( msg?$error_text && msg$error_text in ignored_errors )
 		{
-		if ( c?$krb ) delete c$krb;
-		return;
-		}
-
-	if ( c?$krb && c$krb$logged )
-		return;
-
 		if ( c?$krb ) 
-		info = c$krb;
+			delete c$krb;
 
-	if ( ! info?$ts )
+		return;
-		{
-		info$ts  = network_time();
-		info$uid = c$uid;
-		info$id  = c$id;
 		}
 
-	if ( ! info?$client && ( msg?$client_name || msg?$client_realm ) )
+	if ( ! c$krb?$client && ( msg?$client_name || msg?$client_realm ) )
-		info$client = fmt("%s%s", msg?$client_name ? msg$client_name + "/" : "",
+		c$krb$client = fmt("%s%s", msg?$client_name ? msg$client_name + "/" : "",
 		                           msg?$client_realm ? msg$client_realm : "");
 
-	info$service = msg$service_name;
+	c$krb$service    = msg$service_name;
-	info$success = F;
+	c$krb$success    = F;
+	c$krb$error_code = msg$error_code;
 
-	info$error_code = msg$error_code;
+	if ( msg?$error_text )
-
+		c$krb$error_msg = msg$error_text;
-	if ( msg?$error_text )			info$error_msg = msg$error_text;
+	else if ( msg$error_code in error_msg )
-	else if ( msg$error_code in error_msg ) info$error_msg = error_msg[msg$error_code];
+		c$krb$error_msg = error_msg[msg$error_code];
-
-	c$krb = info;
 	}
 
 event krb_error(c: connection, msg: Error_Msg) &priority=-5
 	{
-	if ( c?$krb )
+	do_log(c);
-		{
-		Log::write(KRB::LOG, c$krb);
-		c$krb$logged = T;
-		}
 	}
 
 event krb_as_request(c: connection, msg: KDC_Request) &priority=5
 	{
-	if ( c?$krb && c$krb$logged )
+	if ( set_session(c) )
 		return;
 
-	local info: Info;
+	c$krb$request_type = "AS";
-
+	c$krb$client       = fmt("%s/%s", msg?$client_name ? msg$client_name : "", msg$service_realm);
-	if ( !c?$krb )
+	c$krb$service      = msg$service_name;
-		{
-		info$ts  = network_time();
-		info$uid = c$uid;
-		info$id  = c$id;
-		}
-	else
-		info = c$krb;
-
-	info$request_type = "AS";
-	info$client = fmt("%s/%s", msg?$client_name ? msg$client_name : "", msg$service_realm);
-	info$service = msg$service_name;
 
 	if ( msg?$from )
-		info$from = msg$from;
+		c$krb$from = msg$from;
+	c$krb$till        = msg$till;
 
-	info$till = msg$till;
+	c$krb$forwardable = msg$kdc_options$forwardable;
-
+	c$krb$renewable   = msg$kdc_options$renewable;
-	info$forwardable = msg$kdc_options$forwardable;
-	info$renewable = msg$kdc_options$renewable;
-
-	c$krb = info;
-	}
-
-event krb_tgs_request(c: connection, msg: KDC_Request) &priority=5
-	{
-	if ( c?$krb && c$krb$logged )
-		return;
-
-	local info: Info;
-	info$ts  = network_time();
-	info$uid = c$uid;
-	info$id  = c$id;
-	info$request_type = "TGS";
-	info$service = msg$service_name;
-	if ( msg?$from ) info$from = msg$from;
-	info$till = msg$till;
-
-	info$forwardable = msg$kdc_options$forwardable;
-	info$renewable = msg$kdc_options$renewable;
-
-	c$krb = info;
 	}
 
 event krb_as_response(c: connection, msg: KDC_Response) &priority=5
 	{
-	local info: Info;
+	if ( set_session(c) )
-
-	if ( c?$krb && c$krb$logged )
 		return;
 
-	if ( c?$krb )
+	if ( ! c$krb?$client && ( msg?$client_name || msg?$client_realm ) )
-		info = c$krb;
-
-	if ( ! info?$ts )
 		{
-		info$ts  = network_time();
+		c$krb$client = fmt("%s/%s", msg?$client_name ? msg$client_name : "", 
-		info$uid = c$uid;
+	                                msg?$client_realm ? msg$client_realm : "");
-		info$id  = c$id;
 		}
 
-	if ( ! info?$client && ( msg?$client_name || msg?$client_realm ) )
+	c$krb$service = msg$ticket$service_name;
-		info$client = fmt("%s/%s", msg?$client_name ? msg$client_name : "", msg?$client_realm ? msg$client_realm : "");
+	c$krb$cipher  = cipher_name[msg$ticket$cipher];
-
+	c$krb$success = T;
-	info$service = msg$ticket$service_name;
-	info$cipher  = cipher_name[msg$ticket$cipher];
-	info$success = T;
-
-	c$krb = info;
 	}
 
 event krb_as_response(c: connection, msg: KDC_Response) &priority=-5
 	{
-	Log::write(KRB::LOG, c$krb);
+	do_log(c);
-	c$krb$logged = T;
+	}
+
+event krb_ap_request(c: connection, ticket: KRB::Ticket, opts: KRB::AP_Options) &priority=5
+	{
+	if ( set_session(c) )
+		return;
+	}
+
+event krb_tgs_request(c: connection, msg: KDC_Request) &priority=5
+	{
+	if ( set_session(c) )
+		return;
+
+	c$krb$request_type = "TGS";
+	c$krb$service = msg$service_name;
+	if ( msg?$from ) 
+		c$krb$from = msg$from;
+	c$krb$till = msg$till;
+
+	c$krb$forwardable = msg$kdc_options$forwardable;
+	c$krb$renewable   = msg$kdc_options$renewable;
 	}
 
 event krb_tgs_response(c: connection, msg: KDC_Response) &priority=5
 	{
-	local info: Info;
+	if ( set_session(c) )
-
-	if ( c?$krb && c$krb$logged )
 		return;
 
-	if ( c?$krb )
+	if ( ! c$krb?$client && ( msg?$client_name || msg?$client_realm ) )
-		info = c$krb;
-
-	if ( ! info?$ts )
 		{
-		info$ts  = network_time();
+		c$krb$client = fmt("%s/%s", msg?$client_name ? msg$client_name : "", 
-		info$uid = c$uid;
+	                                msg?$client_realm ? msg$client_realm : "");
-		info$id  = c$id;
 		}
 
-	if ( ! info?$client && ( msg?$client_name || msg?$client_realm ) )
+	c$krb$service = msg$ticket$service_name;
-		info$client = fmt("%s/%s", msg?$client_name ? msg$client_name : "", msg?$client_realm ? msg$client_realm : "");
+	c$krb$cipher  = cipher_name[msg$ticket$cipher];
-
+	c$krb$success = T;
-	info$service = msg$ticket$service_name;
-	info$cipher  = cipher_name[msg$ticket$cipher];
-	info$success = T;
-
-	c$krb = info;
 	}
 
 event krb_tgs_response(c: connection, msg: KDC_Response) &priority=-5
 	{
-	Log::write(KRB::LOG, c$krb);
+	do_log(c);
-	c$krb$logged = T;
 	}
 
 event connection_state_remove(c: connection) &priority=-5
 	{
-	if ( c?$krb && ! c$krb$logged )
+	do_log(c);
-		Log::write(KRB::LOG, c$krb);
 	}

scripts/policy/protocols/krb/ticket-logging.bro

@@ -0,0 +1,33 @@
+##! Add Kerberos ticket hashes to the krb.log
+
+@load base/protocols/krb
+
+module KRB;
+
+redef record Info += {
+	## Hash of ticket used to authorize request/transaction
+	auth_ticket: string &log &optional;
+	## Hash of ticket returned by the KDC
+	new_ticket:  string &log &optional;
+};
+
+event krb_ap_request(c: connection, ticket: KRB::Ticket, opts: KRB::AP_Options)
+	{
+	# Will be overwritten when request is a TGS
+	c$krb$request_type = "AP";
+
+	if ( ticket?$ciphertext )
+		c$krb$auth_ticket = md5_hash(ticket$ciphertext);
+	}
+
+event krb_as_response(c: connection, msg: KDC_Response)
+	{
+	if ( msg$ticket?$ciphertext )
+		c$krb$new_ticket = md5_hash(msg$ticket$ciphertext);
+	}
+
+event krb_tgs_response(c: connection, msg: KDC_Response)
+	{
+	if ( msg$ticket?$ciphertext )
+		c$krb$new_ticket = md5_hash(msg$ticket$ciphertext);
+	}

scripts/test-all-policy.bro

@@ -72,6 +72,7 @@
 @load protocols/http/software.bro
 @load protocols/http/var-extraction-cookies.bro
 @load protocols/http/var-extraction-uri.bro
+@load protocols/krb/ticket-logging.bro
 @load protocols/modbus/known-masters-slaves.bro
 @load protocols/modbus/track-memmap.bro
 @load protocols/mysql/software.bro

src/analyzer/protocol/krb/krb-types.pac

@@ -95,6 +95,7 @@ RecordVal* proc_ticket(const KRB_Ticket* ticket)
 	rv->Assign(1, bytestring_to_val(ticket->realm()->data()->content()));
 	rv->Assign(2, GetStringFromPrincipalName(ticket->sname()));
 	rv->Assign(3, asn1_integer_to_val(ticket->enc_part()->data()->etype()->data(), TYPE_COUNT));
+	rv->Assign(4, bytestring_to_val(ticket->enc_part()->data()->ciphertext()));
 
 	return rv;
 }

testing/btest/Baseline/plugins.hooks/output

@@ -247,7 +247,7 @@
 0.000000   MetaHookPost  CallFunction(Log::__create_stream, <frame>, (Weird::LOG, [columns=<no value description>, ev=Weird::log_weird, path=weird])) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::__create_stream, <frame>, (X509::LOG, [columns=<no value description>, ev=X509::log_x509, path=x509])) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::__create_stream, <frame>, (mysql::LOG, [columns=<no value description>, ev=MySQL::log_mysql, path=mysql])) -> <no result>
-0.000000   MetaHookPost  CallFunction(Log::__write, <frame>, (PacketFilter::LOG, [ts=1485327769.512366, node=bro, filter=ip or not ip, init=T, success=T])) -> <no result>
+0.000000   MetaHookPost  CallFunction(Log::__write, <frame>, (PacketFilter::LOG, [ts=1487443758.386684, node=bro, filter=ip or not ip, init=T, success=T])) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::add_default_filter, <frame>, (Cluster::LOG)) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::add_default_filter, <frame>, (Communication::LOG)) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::add_default_filter, <frame>, (Conn::LOG)) -> <no result>
@@ -377,7 +377,7 @@
 0.000000   MetaHookPost  CallFunction(Log::create_stream, <frame>, (Weird::LOG, [columns=<no value description>, ev=Weird::log_weird, path=weird])) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::create_stream, <frame>, (X509::LOG, [columns=<no value description>, ev=X509::log_x509, path=x509])) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::create_stream, <frame>, (mysql::LOG, [columns=<no value description>, ev=MySQL::log_mysql, path=mysql])) -> <no result>
-0.000000   MetaHookPost  CallFunction(Log::write, <frame>, (PacketFilter::LOG, [ts=1485327769.512366, node=bro, filter=ip or not ip, init=T, success=T])) -> <no result>
+0.000000   MetaHookPost  CallFunction(Log::write, <frame>, (PacketFilter::LOG, [ts=1487443758.386684, node=bro, filter=ip or not ip, init=T, success=T])) -> <no result>
 0.000000   MetaHookPost  CallFunction(NetControl::check_plugins, <frame>, ()) -> <no result>
 0.000000   MetaHookPost  CallFunction(NetControl::init, <null>, ()) -> <no result>
 0.000000   MetaHookPost  CallFunction(Notice::want_pp, <frame>, ()) -> <no result>
@@ -968,7 +968,7 @@
 0.000000   MetaHookPre   CallFunction(Log::__create_stream, <frame>, (Weird::LOG, [columns=<no value description>, ev=Weird::log_weird, path=weird]))
 0.000000   MetaHookPre   CallFunction(Log::__create_stream, <frame>, (X509::LOG, [columns=<no value description>, ev=X509::log_x509, path=x509]))
 0.000000   MetaHookPre   CallFunction(Log::__create_stream, <frame>, (mysql::LOG, [columns=<no value description>, ev=MySQL::log_mysql, path=mysql]))
-0.000000   MetaHookPre   CallFunction(Log::__write, <frame>, (PacketFilter::LOG, [ts=1485327769.512366, node=bro, filter=ip or not ip, init=T, success=T]))
+0.000000   MetaHookPre   CallFunction(Log::__write, <frame>, (PacketFilter::LOG, [ts=1487443758.386684, node=bro, filter=ip or not ip, init=T, success=T]))
 0.000000   MetaHookPre   CallFunction(Log::add_default_filter, <frame>, (Cluster::LOG))
 0.000000   MetaHookPre   CallFunction(Log::add_default_filter, <frame>, (Communication::LOG))
 0.000000   MetaHookPre   CallFunction(Log::add_default_filter, <frame>, (Conn::LOG))
@@ -1098,7 +1098,7 @@
 0.000000   MetaHookPre   CallFunction(Log::create_stream, <frame>, (Weird::LOG, [columns=<no value description>, ev=Weird::log_weird, path=weird]))
 0.000000   MetaHookPre   CallFunction(Log::create_stream, <frame>, (X509::LOG, [columns=<no value description>, ev=X509::log_x509, path=x509]))
 0.000000   MetaHookPre   CallFunction(Log::create_stream, <frame>, (mysql::LOG, [columns=<no value description>, ev=MySQL::log_mysql, path=mysql]))
-0.000000   MetaHookPre   CallFunction(Log::write, <frame>, (PacketFilter::LOG, [ts=1485327769.512366, node=bro, filter=ip or not ip, init=T, success=T]))
+0.000000   MetaHookPre   CallFunction(Log::write, <frame>, (PacketFilter::LOG, [ts=1487443758.386684, node=bro, filter=ip or not ip, init=T, success=T]))
 0.000000   MetaHookPre   CallFunction(NetControl::check_plugins, <frame>, ())
 0.000000   MetaHookPre   CallFunction(NetControl::init, <null>, ())
 0.000000   MetaHookPre   CallFunction(Notice::want_pp, <frame>, ())
@@ -1688,7 +1688,7 @@
 0.000000 | HookCallFunction Log::__create_stream(Weird::LOG, [columns=<no value description>, ev=Weird::log_weird, path=weird])
 0.000000 | HookCallFunction Log::__create_stream(X509::LOG, [columns=<no value description>, ev=X509::log_x509, path=x509])
 0.000000 | HookCallFunction Log::__create_stream(mysql::LOG, [columns=<no value description>, ev=MySQL::log_mysql, path=mysql])
-0.000000 | HookCallFunction Log::__write(PacketFilter::LOG, [ts=1485327769.512366, node=bro, filter=ip or not ip, init=T, success=T])
+0.000000 | HookCallFunction Log::__write(PacketFilter::LOG, [ts=1487443758.386684, node=bro, filter=ip or not ip, init=T, success=T])
 0.000000 | HookCallFunction Log::add_default_filter(Cluster::LOG)
 0.000000 | HookCallFunction Log::add_default_filter(Communication::LOG)
 0.000000 | HookCallFunction Log::add_default_filter(Conn::LOG)
@@ -1818,7 +1818,7 @@
 0.000000 | HookCallFunction Log::create_stream(Weird::LOG, [columns=<no value description>, ev=Weird::log_weird, path=weird])
 0.000000 | HookCallFunction Log::create_stream(X509::LOG, [columns=<no value description>, ev=X509::log_x509, path=x509])
 0.000000 | HookCallFunction Log::create_stream(mysql::LOG, [columns=<no value description>, ev=MySQL::log_mysql, path=mysql])
-0.000000 | HookCallFunction Log::write(PacketFilter::LOG, [ts=1485327769.512366, node=bro, filter=ip or not ip, init=T, success=T])
+0.000000 | HookCallFunction Log::write(PacketFilter::LOG, [ts=1487443758.386684, node=bro, filter=ip or not ip, init=T, success=T])
 0.000000 | HookCallFunction NetControl::check_plugins()
 0.000000 | HookCallFunction NetControl::init()
 0.000000 | HookCallFunction Notice::want_pp()
@@ -2297,6 +2297,7 @@
 1362692527.080972   MetaHookPost  CallFunction(Conn::determine_service, <frame>, ([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>])) -> <no result>
 1362692527.080972   MetaHookPost  CallFunction(Conn::set_conn, <frame>, ([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>], T)) -> <no result>
 1362692527.080972   MetaHookPost  CallFunction(HTTP::get_file_handle, <frame>, ([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>], T)) -> <no result>
+1362692527.080972   MetaHookPost  CallFunction(KRB::do_log, <frame>, ([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>])) -> <no result>
 1362692527.080972   MetaHookPost  CallFunction(KRB::fill_in_subjects, <frame>, ([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>])) -> <no result>
 1362692527.080972   MetaHookPost  CallFunction(Log::__write, <frame>, (Conn::LOG, [ts=1362692526.869344, uid=CHhAvVGS1DHFjwGM9, id=[orig_h=141.142.228.5, orig_p=59856<...>/tcp], proto=tcp, service=http, duration=0.211484, orig_bytes=136, resp_bytes=5007, conn_state=SF, local_orig=<uninitialized>, local_resp=<uninitialized>, missed_bytes=0, history=ShADadFf, orig_pkts=7, orig_ip_bytes=512, resp_pkts=7, resp_ip_bytes=5379, tunnel_parents={}])) -> <no result>
 1362692527.080972   MetaHookPost  CallFunction(Log::write, <frame>, (Conn::LOG, [ts=1362692526.869344, uid=CHhAvVGS1DHFjwGM9, id=[orig_h=141.142.228.5, orig_p=59856<...>/tcp], proto=tcp, service=http, duration=0.211484, orig_bytes=136, resp_bytes=5007, conn_state=SF, local_orig=<uninitialized>, local_resp=<uninitialized>, missed_bytes=0, history=ShADadFf, orig_pkts=7, orig_ip_bytes=512, resp_pkts=7, resp_ip_bytes=5379, tunnel_parents={}])) -> <no result>
@@ -2327,6 +2328,7 @@
 1362692527.080972   MetaHookPre   CallFunction(Conn::determine_service, <frame>, ([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>]))
 1362692527.080972   MetaHookPre   CallFunction(Conn::set_conn, <frame>, ([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>], T))
 1362692527.080972   MetaHookPre   CallFunction(HTTP::get_file_handle, <frame>, ([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>], T))
+1362692527.080972   MetaHookPre   CallFunction(KRB::do_log, <frame>, ([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>]))
 1362692527.080972   MetaHookPre   CallFunction(KRB::fill_in_subjects, <frame>, ([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>]))
 1362692527.080972   MetaHookPre   CallFunction(Log::__write, <frame>, (Conn::LOG, [ts=1362692526.869344, uid=CHhAvVGS1DHFjwGM9, id=[orig_h=141.142.228.5, orig_p=59856<...>/tcp], proto=tcp, service=http, duration=0.211484, orig_bytes=136, resp_bytes=5007, conn_state=SF, local_orig=<uninitialized>, local_resp=<uninitialized>, missed_bytes=0, history=ShADadFf, orig_pkts=7, orig_ip_bytes=512, resp_pkts=7, resp_ip_bytes=5379, tunnel_parents={}]))
 1362692527.080972   MetaHookPre   CallFunction(Log::write, <frame>, (Conn::LOG, [ts=1362692526.869344, uid=CHhAvVGS1DHFjwGM9, id=[orig_h=141.142.228.5, orig_p=59856<...>/tcp], proto=tcp, service=http, duration=0.211484, orig_bytes=136, resp_bytes=5007, conn_state=SF, local_orig=<uninitialized>, local_resp=<uninitialized>, missed_bytes=0, history=ShADadFf, orig_pkts=7, orig_ip_bytes=512, resp_pkts=7, resp_ip_bytes=5379, tunnel_parents={}]))
@@ -2358,6 +2360,7 @@
 1362692527.080972 | HookCallFunction Conn::determine_service([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>])
 1362692527.080972 | HookCallFunction Conn::set_conn([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>], T)
 1362692527.080972 | HookCallFunction HTTP::get_file_handle([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>], T)
+1362692527.080972 | HookCallFunction KRB::do_log([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>])
 1362692527.080972 | HookCallFunction KRB::fill_in_subjects([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>])
 1362692527.080972 | HookCallFunction Log::__write(Conn::LOG, [ts=1362692526.869344, uid=CHhAvVGS1DHFjwGM9, id=[orig_h=141.142.228.5, orig_p=59856<...>/tcp], proto=tcp, service=http, duration=0.211484, orig_bytes=136, resp_bytes=5007, conn_state=SF, local_orig=<uninitialized>, local_resp=<uninitialized>, missed_bytes=0, history=ShADadFf, orig_pkts=7, orig_ip_bytes=512, resp_pkts=7, resp_ip_bytes=5379, tunnel_parents={}])
 1362692527.080972 | HookCallFunction Log::write(Conn::LOG, [ts=1362692526.869344, uid=CHhAvVGS1DHFjwGM9, id=[orig_h=141.142.228.5, orig_p=59856<...>/tcp], proto=tcp, service=http, duration=0.211484, orig_bytes=136, resp_bytes=5007, conn_state=SF, local_orig=<uninitialized>, local_resp=<uninitialized>, missed_bytes=0, history=ShADadFf, orig_pkts=7, orig_ip_bytes=512, resp_pkts=7, resp_ip_bytes=5379, tunnel_parents={}])

testing/btest/Baseline/scripts.base.protocols.krb.kinit/output

@@ -1,3 +1,3 @@
 KRB_AP_REQUEST
-[pvno=5, realm=VLADG.NET, service_name=krbtgt/VLADG.NET, cipher=18]
+[pvno=5, realm=VLADG.NET, service_name=krbtgt/VLADG.NET, cipher=18, ciphertext=\x04\x81\xfa{\x9fY\xd0f\x8dS\xf4I\x88\x04\xfa\xc1\xd8m\xa2\xb7+\xbb\x19\xcag\x0c\x13\xd1g*\xfc\x18\xd1\xb1\x80!\xbd\x85\xec\xf9\x9b\xfa-\x18\xb6\xf5h\x91\xe7\x99\xf4\xdb\x93\xa0\xc7\x90\x1e\xa9\x95v\xd3\x12\xfa,9\x1d\x0b\xd0\xa1\xd25\x0f\x1f[G\xdf\xd0\xbbd\x06$2\xd1\xae\x130qZiY\x07@\xe9\xf9\xff\xa4\x9a\xd4\x09\xf0\x0d\xc1R\x10M\xbdKOV\xfd\xf6\x13\xf6\x9a\x95N\xdf!\xf6x\x94\xd8j\xa5\xdcp\xa8\x04\x99\x02x\xdb$\xd8\xfa_o\x8dV\xc8\x0a\xfe\x00\xf3&c\x0c8\xd1\xd0\xe9\x8e\xab\xfe&\xfe\x00\x8d$\x98I\xe5\x8d\x94rM4%\xd8\xfe\xa9\x08\x06\xc6\x95H7\xf7HCq\xb9\x0d$\x95?\x83B\x82\xdd\xea\xc3f3\xcc\xbb\x09\x0d-\x09;\xa6i%\xcd\xba\x11\xd4\xe0\x12w\xd0G&\xdaj\x82\x7f;\xf3\x1d\x10\xa4l\x06\x16l\x1bc\xa1\xd1\x15!\x00\x8a\xff\x8a\x06\xe7U^:<d\xba"\x02I\xf0\xce\xc7\xad\xb2]
 [use_session_key=F, mutual_required=F]

testing/btest/Baseline/scripts.policy.protocols.krb.ticket-logging/kerberos.log

@@ -0,0 +1,10 @@
+#separator \x09
+#set_separator	,
+#empty_field	(empty)
+#unset_field	-
+#path	kerberos
+#open	2017-02-18-18-38-58
+#fields	ts	uid	id.orig_h	id.orig_p	id.resp_h	id.resp_p	request_type	client	service	success	error_msg	from	till	cipher	forwardable	renewable	client_cert_subject	client_cert_fuid	server_cert_subject	server_cert_fuid	auth_ticket	new_ticket
+#types	time	string	addr	port	addr	port	string	string	string	bool	string	time	time	string	bool	bool	string	string	string	string	string	string
+1429583645.478441	CHhAvVGS1DHFjwGM9	192.168.1.31	64889	192.168.1.32	88	TGS	vladg/VLADG.NET	krbtgt/VLADG.NET	T	-	-	0.000000	aes256-cts-hmac-sha1-96	T	F	-	-	-	-	ea0f395c3823e8cc7216d82e2405b428	fa8064009b03606f84e475feca5dcd12
+#close	2017-02-18-18-38-58

testing/btest/scripts/policy/protocols/krb/ticket-logging.bro

@@ -0,0 +1,6 @@
+# This test makes sure that krb ticket hashes are logged correctly.
+
+# @TEST-EXEC: bro -b -r $TRACES/krb/auth.trace %INPUT
+# @TEST-EXEC: btest-diff kerberos.log
+
+@load protocols/krb/ticket-logging