Allow to track service violations in conn.log.

This introduces ian options, DPD::track_removed_services_in_connection.
It adds failed services to the services column, prefixed with a
"-".

Alternatively, this commit also adds
policy/protocols/conn/failed-services.zeek, which provides the same
information in a new column in conn.log.

scripts/base/frameworks/analyzer/dpd.zeek

@@ -35,13 +35,16 @@ export {
 	## Ignore violations which go this many bytes into the connection.
 	## Set to 0 to never ignore protocol violations.
 	option ignore_violations_after = 10 * 1024;
+
+	## Add removed services to conn.log, with a - in front of them.
+	option track_removed_services_in_connection = F;
 }
 
 redef record connection += {
 	dpd: Info &optional;
 	## The set of services (analyzers) for which Zeek has observed a
 	## violation after the same service had previously been confirmed.
-	service_violation: set[string] &default=set();
+	service_violation: set[string] &default=set() &ordered;
 };
 
 event zeek_init() &priority=5
@@ -77,9 +80,6 @@ event analyzer_violation_info(atype: AllAnalyzers::Tag, info: AnalyzerViolationI
 	if ( analyzer !in c$service || analyzer in c$service_violation )
 		return;
 
-	# No longer delete a service once it has been confirmed.
-	# FIXME: track failed analyzers somehow - either by changing how they are logged, or by adding a new column
-	# delete c$service[analyzer];
 	add c$service_violation[analyzer];
 
 	local dpd: Info;
@@ -120,7 +120,16 @@ event analyzer_violation_info(atype: AllAnalyzers::Tag, info: AnalyzerViolationI
 	if ( ignore_violations_after > 0 && size > ignore_violations_after )
 		return;
 
-	disable_analyzer(c$id, aid, F);
+	local disabled = disable_analyzer(c$id, aid, F);
+
+	# add "-service" to the list of services on removal due to violation, if analyzer was confirmed before
+	if ( track_removed_services_in_connection && disabled && Analyzer::name(atype) in c$service )
+		{
+		local rname = fmt("-%s", Analyzer::name(atype));
+		if ( rname !in c$service )
+			add c$service[rname];
+		}
+
 	}
 
 event analyzer_violation_info(atype: AllAnalyzers::Tag, info: AnalyzerViolationInfo ) &priority=-5

scripts/base/protocols/conn/main.zeek

@@ -31,6 +31,9 @@ export {
 		## the connection. Can list more than one protocol separated with
 		## colons. Protocols listed are in the order in which they are
 		## confirmed.
+		## This field can also contain a list of protocol analyzers that
+		## raise violations prefixed with a "-" if the option
+		## :zeek:see:`DPD::track_removed_services_in_connection` is set.
 		service:      string          &log &optional;
 		## How long the connection lasted.
 		##

scripts/policy/protocols/conn/failed-services.zeek

@@ -0,0 +1,27 @@
+##! This script adds the new column ``service_violation`` to the connection log.
+##! The column contains the list of protocols in a connection that raised protocol
+##! violations causing the analyzer to be removed. Protocols are listed in order
+##! that they were removed.
+
+@load base/protocols/conn
+
+module Conn;
+
+redef record Conn::Info += {
+	## List of protocols in a connection that raised protocol violations
+	## causing the analyzer to be removed.
+	## Protocols are listed in order that they were removed.
+	service_violation: vector of string  &log &optional;
+};
+
+# Not using connection removal hook, as this has to run for every connection.
+event connection_state_remove(c: connection) &priority=4
+	{
+	if ( c?$conn && |c$service_violation| > 0 )
+		{
+		c$conn$service_violation = {};
+		local sv: string;
+		for ( sv in c$service_violation)
+			c$conn$service_violation += to_lower(sv);
+		}
+	}

scripts/test-all-policy.zeek

@@ -98,6 +98,7 @@
 @load misc/unknown-protocols.zeek
 @load protocols/conn/community-id-logging.zeek
 @load protocols/conn/disable-unknown-ip-proto-support.zeek
+@load protocols/conn/failed-services.zeek
 @load protocols/conn/ip-proto-name-logging.zeek
 @load protocols/conn/known-hosts.zeek
 @load protocols/conn/known-services.zeek

testing/btest/Baseline/plugins.hooks/output

@@ -118,6 +118,7 @@
 0.000000   MetaHookPost  CallFunction(Option::set_change_handler, <frame>, (DPD::ignore_violations, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100)) -> <no result>
 0.000000   MetaHookPost  CallFunction(Option::set_change_handler, <frame>, (DPD::ignore_violations_after, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100)) -> <no result>
 0.000000   MetaHookPost  CallFunction(Option::set_change_handler, <frame>, (DPD::max_violations, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100)) -> <no result>
+0.000000   MetaHookPost  CallFunction(Option::set_change_handler, <frame>, (DPD::track_removed_services_in_connection, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100)) -> <no result>
 0.000000   MetaHookPost  CallFunction(Option::set_change_handler, <frame>, (Files::enable_reassembler, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100)) -> <no result>
 0.000000   MetaHookPost  CallFunction(Option::set_change_handler, <frame>, (HTTP::default_capture_password, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100)) -> <no result>
 0.000000   MetaHookPost  CallFunction(Option::set_change_handler, <frame>, (HTTP::http_methods, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100)) -> <no result>
@@ -1064,6 +1065,7 @@
 0.000000   MetaHookPre   CallFunction(Option::set_change_handler, <frame>, (DPD::ignore_violations, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100))
 0.000000   MetaHookPre   CallFunction(Option::set_change_handler, <frame>, (DPD::ignore_violations_after, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100))
 0.000000   MetaHookPre   CallFunction(Option::set_change_handler, <frame>, (DPD::max_violations, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100))
+0.000000   MetaHookPre   CallFunction(Option::set_change_handler, <frame>, (DPD::track_removed_services_in_connection, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100))
 0.000000   MetaHookPre   CallFunction(Option::set_change_handler, <frame>, (Files::enable_reassembler, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100))
 0.000000   MetaHookPre   CallFunction(Option::set_change_handler, <frame>, (HTTP::default_capture_password, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100))
 0.000000   MetaHookPre   CallFunction(Option::set_change_handler, <frame>, (HTTP::http_methods, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100))
@@ -2009,6 +2011,7 @@
 0.000000 | HookCallFunction Option::set_change_handler(DPD::ignore_violations, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100)
 0.000000 | HookCallFunction Option::set_change_handler(DPD::ignore_violations_after, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100)
 0.000000 | HookCallFunction Option::set_change_handler(DPD::max_violations, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100)
+0.000000 | HookCallFunction Option::set_change_handler(DPD::track_removed_services_in_connection, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100)
 0.000000 | HookCallFunction Option::set_change_handler(Files::enable_reassembler, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100)
 0.000000 | HookCallFunction Option::set_change_handler(HTTP::default_capture_password, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100)
 0.000000 | HookCallFunction Option::set_change_handler(HTTP::http_methods, Config::config_option_changed: function(ID:string, new_value:any, location:string) : any{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerce Config::log)return (Config::new_value)}, -100)

testing/btest/Baseline/scripts.base.frameworks.analyzer.dpd-logging-configuration/conn.log

@@ -0,0 +1,11 @@
+### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
+#separator \x09
+#set_separator	,
+#empty_field	(empty)
+#unset_field	-
+#path	conn
+#open XXXX-XX-XX-XX-XX-XX
+#fields	ts	uid	id.orig_h	id.orig_p	id.resp_h	id.resp_p	proto	service	duration	orig_bytes	resp_bytes	conn_state	local_orig	local_resp	missed_bytes	history	orig_pkts	orig_ip_bytes	resp_pkts	resp_ip_bytes	tunnel_parents	ip_proto	service_violation
+#types	time	string	addr	port	addr	port	enum	string	interval	count	count	string	bool	bool	count	string	count	count	count	count	set[string]	count	vector[string]
+XXXXXXXXXX.XXXXXX	CHhAvVGS1DHFjwGM9	127.0.0.1	51354	127.0.0.1	21	tcp	ftp,-ftp	9.891089	34	71	SF	T	T	0	ShAdDaFf	13	718	10	599	-	6	ftp
+#close XXXX-XX-XX-XX-XX-XX

testing/btest/scripts/base/frameworks/analyzer/dpd-logging-configuration.zeek

@@ -0,0 +1,7 @@
+# @TEST-DOC: Check if DPD options on violations work.
+# @TEST-EXEC: zeek -r $TRACES/ftp/ftp-invalid-reply-code.pcap %INPUT
+# @TEST-EXEC: btest-diff conn.log
+
+@load policy/protocols/conn/failed-services
+
+redef DPD::track_removed_services_in_connection = T;

testing/btest/scripts/base/protocols/ftp/ftp-invalid-reply-code.zeek

@@ -1,4 +1,4 @@
-# @TEST-DOC: Th server replies with a line that does not contain a numeric code.: violation.
+# @TEST-DOC: The server replies with a line that does not contain a numeric code: violation.
 # @TEST-EXEC: zeek -b -r $TRACES/ftp/ftp-invalid-reply-code.pcap %INPUT
 # @TEST-EXEC: btest-diff conn.log
 # @TEST-EXEC: btest-diff ftp.log