GH-1221: Add unknown_protocols.log for logging packet analyzer lookup failures

NEWS

@@ -66,6 +66,12 @@ New Functionality
   ``dump-events.zeek`` script to log all events that happen; the script
   got a new option to enable this behavior.
 
+- Added new unknown_protocols.log that will log analyzer and protocol pairs
+  via the packet analysis framework for packet protocols that aren't
+  supported by Zeek. It can be enabled by loading the
+  ``policy/misc/unknown-protocols`` script. The script adds a new
+  ``unknown_protocol`` event.
+
 Changed Functionality
 ---------------------
 

doc

@@ -1 +1 @@
-Subproject commit 2e5ef4b5a6752d53a4145b5b5b9da6f0bd4735a8
+Subproject commit e6d31de9d8f35815cfb0f5a361ca1fdbe3d443ed

scripts/policy/misc/unknown-protocols.zeek

@@ -0,0 +1,64 @@
+##! This script logs information about packet protocols that Zeek doesn't
+##! know how to process. Mostly these come from packet analysis plugins when
+##! they attempt to forward to the next analyzer, but they also can originate
+##! from non-packet analyzers.
+
+@load base/frameworks/notice
+
+module UnknownProtocol;
+
+export {
+	redef enum Log::ID += { LOG };
+
+	global log_policy: Log::PolicyHook;
+
+	type Info: record {
+		## Timestamp for when the measurement occurred.
+		ts:           time     &log;
+
+		## The string name of the analyzer attempting to forward the protocol.
+		analyzer:     string   &log;
+
+		## The identifier of the protocol being forwarded.
+		protocol_id:  string   &log;
+
+		## A certain number of bytes at the start of the unknown protocol's
+		## header.
+		first_bytes:  string   &log;
+	};
+
+	## How many reports for an analyzer/protocol pair will be allowed to
+	## raise events before becoming rate-limited.
+	const sampling_threshold : count = 3 &redef;
+
+	## The rate-limiting sampling rate. One out of every of this number of
+	## rate-limited pairs of a given type will be allowed to raise events
+	## for further script-layer handling. Setting the sampling rate to 0
+	## will disable all output of rate-limited pairs.
+	const sampling_rate : count = 100000 &redef;
+
+	## How long an analyzer/protocol pair is allowed to keep state/counters in
+	## in memory. Once the threshold has been hit, this is the amount of time
+	## before the rate-limiting for a pair expires and is reset.
+	const sampling_duration = 1hr &redef;
+
+	## The number of bytes to extract from the next header and log in the
+	## first bytes field.
+	const first_bytes_count = 10 &redef;
+}
+
+event unknown_protocol(analyzer_name: string, protocol: count, first_bytes: string)
+	{
+	local info : Info;
+	info$ts = network_time();
+	info$analyzer = analyzer_name;
+	info$protocol_id = fmt("0x%x", protocol);
+	info$first_bytes = bytestring_to_hexstr(first_bytes);
+
+	Log::write(LOG, info);
+	}
+
+event zeek_init() &priority=5
+	{
+	Log::create_stream(LOG, [$columns=Info, $path="unknown_protocols", $policy=log_policy]);
+	}

scripts/test-all-policy.zeek

@@ -62,6 +62,7 @@
 @load misc/stats.zeek
 @load misc/weird-stats.zeek
 @load misc/trim-trace-file.zeek
+@load misc/unknown-protocols.zeek
 @load protocols/conn/known-hosts.zeek
 @load protocols/conn/known-services.zeek
 @load protocols/conn/mac-logging.zeek

src/Timer.cc

@@ -47,6 +47,7 @@ const char* TimerNames[] = {
 	"ParentProcessIDCheck",
 	"TimerMgrExpireTimer",
 	"ThreadHeartbeat",
+	"UnknownProtocolExpire",
 };
 
 const char* timer_type_to_string(TimerType type)

src/Timer.h

@@ -45,8 +45,9 @@ enum TimerType : uint8_t {
 	TIMER_PPID_CHECK,
 	TIMER_TIMERMGR_EXPIRE,
 	TIMER_THREAD_HEARTBEAT,
+	TIMER_UNKNOWN_PROTOCOL_EXPIRE,
 };
-constexpr int NUM_TIMER_TYPES = int(TIMER_THREAD_HEARTBEAT) + 1;
+constexpr int NUM_TIMER_TYPES = int(TIMER_UNKNOWN_PROTOCOL_EXPIRE) + 1;
 
 extern const char* timer_type_to_string(TimerType type);
 

src/event.bif

@@ -876,3 +876,15 @@ event anonymization_mapping%(orig: addr, mapped: addr%);
 ##
 ## path: the filesystem path of the pcap file
 event Pcap::file_done%(path: string%);
+
+## Generated when a packet analyzer attempts to forward a protocol that it doesn't
+## know how to handle.
+##
+## analzyer_name: The string name of the analyzer attempting to forward the protocol
+##
+## protocol: The identifier of the protocol being forwarded
+##
+## first_bytes: A certain number of bytes at the start of the unknown protocol's header.
+##
+## .. zeek:see:: UnknownProtocol::first_bytes_count
+event unknown_protocol%(analyzer_name: string, protocol: count, first_bytes: string%);

src/packet_analysis/Analyzer.cc

@@ -80,7 +80,7 @@ bool Analyzer::ForwardPacket(size_t len, const uint8_t* data, Packet* packet,
 		{
 		DBG_LOG(DBG_PACKET_ANALYSIS, "Analysis in %s failed, could not find analyzer for identifier %#x.",
 				GetAnalyzerName(), identifier);
-		packet->Weird("no_suitable_analyzer_found");
+		packet_mgr->ReportUnknownProtocol(GetAnalyzerName(), identifier, data, len);
 		return false;
 		}
 

src/packet_analysis/Manager.cc

@@ -43,6 +43,14 @@ void Manager::InitPostScript()
 		pkt_profiler = new detail::PacketProfiler(detail::pkt_profile_mode,
 		                                          detail::pkt_profile_freq,
 		                                          pkt_profile_file->AsFile());
+
+	if ( unknown_protocol )
+		{
+		unknown_sampling_rate = id::find_val("UnknownProtocol::sampling_rate")->AsCount();
+		unknown_sampling_threshold = id::find_val("UnknownProtocol::sampling_threshold")->AsCount();
+		unknown_sampling_duration = id::find_val("UnknownProtocol::sampling_duration")->AsInterval();
+		unknown_first_bytes_count = id::find_val("UnknownProtocol::first_bytes_count")->AsCount();
+		}
 	}
 
 void Manager::Done()
@@ -171,3 +179,62 @@ void Manager::DumpPacket(const Packet *pkt, int len)
 
 	run_state::detail::pkt_dumper->Dump(pkt);
 	}
+
+class UnknownProtocolTimer final : public zeek::detail::Timer {
+public:
+	// Represents a combination of an analyzer name and protocol identifier, where the identifier was
+	// reported as unknown by the analyzer.
+	using UnknownProtocolPair = std::pair<std::string, uint32_t>;
+
+	UnknownProtocolTimer(double t, UnknownProtocolPair p, double timeout)
+		: zeek::detail::Timer(t + timeout, zeek::detail::TIMER_UNKNOWN_PROTOCOL_EXPIRE),
+		  unknown_protocol(std::move(p))
+		{}
+
+	void Dispatch(double t, bool is_expire) override
+		{ zeek::packet_mgr->ResetUnknownProtocolTimer(unknown_protocol.first, unknown_protocol.second); }
+
+	UnknownProtocolPair unknown_protocol;
+};
+
+void Manager::ResetUnknownProtocolTimer(const std::string& analyzer, uint32_t protocol)
+	{
+	unknown_protocols.erase(std::make_pair(analyzer, protocol));
+	}
+
+bool Manager::PermitUnknownProtocol(const std::string& analyzer, uint32_t protocol)
+	{
+	auto p = std::make_pair(analyzer, protocol);
+	uint64_t& count = unknown_protocols[p];
+	++count;
+
+	if ( count == 1 )
+		detail::timer_mgr->Add(new UnknownProtocolTimer(run_state::network_time, p,
+		                                                unknown_sampling_duration));
+
+	if ( count < unknown_sampling_threshold )
+		return true;
+
+	auto num_above_threshold = count - unknown_sampling_threshold;
+	if ( unknown_sampling_rate )
+		return num_above_threshold % unknown_sampling_rate == 0;
+
+	return false;
+	}
+
+void Manager::ReportUnknownProtocol(const std::string& analyzer, uint32_t protocol,
+                                    const uint8_t* data, size_t len)
+	{
+	if ( unknown_protocol )
+		{
+		if ( PermitUnknownProtocol(analyzer, protocol ) )
+			{
+			int bytes_len = std::min(unknown_first_bytes_count, static_cast<uint64_t>(len));
+
+			event_mgr.Enqueue(unknown_protocol,
+			                  make_intrusive<StringVal>(analyzer),
+			                  val_mgr->Count(protocol),
+			                  make_intrusive<StringVal>(bytes_len, (const char*) data));
+			}
+		}
+	}

src/packet_analysis/Manager.h

@@ -92,6 +92,25 @@ public:
 	 */
 	void DumpPacket(const Packet *pkt, int len=0);
 
+	/**
+	 * Attempts to write an entry to unknown_protocols.log, rate-limited to avoid
+	 * spamming the log with duplicates.
+	 *
+	 * @param analyzer The name of the analyzer that was trying to forward the packet.
+	 * @param protocol The protocol of the next header that couldn't be forwarded.
+	 * @param data A pointer to the data of the next header being processed. If this
+	 * is passed as a nullptr, the first_bytes log column will be blank.
+	 * @param len The remaining length of the data in the packet being processed.
+	 */
+	void ReportUnknownProtocol(const std::string& analyzer, uint32_t protocol,
+	                           const uint8_t* data=nullptr, size_t len=0);
+
+	/**
+	 * Callback method for UnknownProtocolTimer to remove an analyzer/protocol
+	 * pair from the map so that it can be logged again.
+	 */
+	void ResetUnknownProtocolTimer(const std::string& analyzer, uint32_t protocol);
+
 private:
 	/**
 	 * Instantiates a new analyzer instance.
@@ -113,11 +132,21 @@ private:
 	 */
 	AnalyzerPtr InstantiateAnalyzer(const std::string& name);
 
+	bool PermitUnknownProtocol(const std::string& analyzer, uint32_t protocol);
+
 	std::map<std::string, AnalyzerPtr> analyzers;
 	AnalyzerPtr root_analyzer = nullptr;
 
 	uint64_t num_packets_processed = 0;
 	detail::PacketProfiler* pkt_profiler = nullptr;
+
+	using UnknownProtocolPair = std::pair<std::string, uint32_t>;
+	std::map<UnknownProtocolPair, uint64_t> unknown_protocols;
+
+	uint64_t unknown_sampling_threshold;
+	uint64_t unknown_sampling_rate;
+	double unknown_sampling_duration;
+	uint64_t unknown_first_bytes_count;
 };
 
 } // namespace packet_analysis

testing/btest/Baseline/core.disable-mobile-ipv6/unknown_protocols.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	unknown_protocols
+#open XXXX-XX-XX-XX-XX-XX
+#fields	ts	analyzer	protocol_id	first_bytes
+#types	time	string	string	string
+XXXXXXXXXX.XXXXXX	IP	0x87	3b010600d1da0080002a
+#close XXXX-XX-XX-XX-XX-XX

testing/btest/Baseline/coverage.find-bro-logs/out

@@ -1,3 +1,4 @@
+### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
 barnyard2
 broker
 capture_loss
@@ -59,6 +60,7 @@ syslog
 traceroute
 tunnel
 unified2
+unknown_protocols
 weird
 weird_stats
 x509

testing/btest/Baseline/plugins.packet-protocol/output_build

@@ -1,3 +1,4 @@
+### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
 PacketDemo::Bar - Demo packet analyzers (RawLayer, LLC). (dynamic, version 1.0.0)
     [Packet Analyzer] LLC_Demo (ANALYZER_LLC_DEMO)
     [Packet Analyzer] Raw_Layer (ANALYZER_RAW_LAYER)

testing/btest/Baseline/plugins.packet-protocol/output_llc

@@ -1,3 +1,4 @@
+### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
 llc_demo_message (DSAP = 42, SSAP = 42, Control = 3)
 llc_demo_message (DSAP = 42, SSAP = 42, Control = 3)
 llc_demo_message (DSAP = 42, SSAP = 42, Control = 3)

testing/btest/Baseline/plugins.packet-protocol/output_orig

@@ -1,20 +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
+#path	unknown_protocols
-#open	2020-10-14-18-47-28
+#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
+#fields	ts	analyzer	protocol_id	first_bytes
-#types	time	string	addr	port	addr	port	enum	string	interval	count	count	string	bool	bool	count	string	count	count	count	count	set[string]
+#types	time	string	string	string
-1599068759.619112	CHhAvVGS1DHFjwGM9	172.22.214.60	8	192.0.78.212	0	icmp	-	-	-	-	OTH	-	-	0	-	1	28	0	0	-
+XXXXXXXXXX.XXXXXX	ETHERNET	0x88b5	4920616d20656e636170
-#close	2020-10-14-18-47-28
+#close XXXX-XX-XX-XX-XX-XX
-#separator \x09
-#set_separator	,
-#empty_field	(empty)
-#unset_field	-
-#path	weird
-#open	2020-10-14-18-47-28
-#fields	ts	uid	id.orig_h	id.orig_p	id.resp_h	id.resp_p	name	addl	notice	peer
-#types	time	string	addr	port	addr	port	string	string	bool	string
-1599068759.647566	-	108.97.116.105	0	110.103.32.73	0	truncated_IPv6	-	F	zeek
-#close	2020-10-14-18-47-28

testing/btest/Baseline/plugins.packet-protocol/output_raw

@@ -1,12 +1,13 @@
+### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
 raw_layer_message (Message = 'I am encapsulating IP', Protocol = 4950)
 #separator \x09
 #set_separator	,
 #empty_field	(empty)
 #unset_field	-
 #path	conn
-#open	2020-10-14-18-47-51
+#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
 #types	time	string	addr	port	addr	port	enum	string	interval	count	count	string	bool	bool	count	string	count	count	count	count	set[string]
-1599068759.647566	ClEkJM2Vm5giqnMf4h	172.22.214.60	8	192.0.78.150	0	icmp	-	-	-	-	OTH	-	-	0	-	1	28	0	0	-
+XXXXXXXXXX.XXXXXX	ClEkJM2Vm5giqnMf4h	172.22.214.60	8	192.0.78.150	0	icmp	-	-	-	-	OTH	-	-	0	-	1	28	0	0	-
-1599068759.619112	CHhAvVGS1DHFjwGM9	172.22.214.60	8	192.0.78.212	0	icmp	-	-	-	-	OTH	-	-	0	-	1	28	0	0	-
+XXXXXXXXXX.XXXXXX	CHhAvVGS1DHFjwGM9	172.22.214.60	8	192.0.78.212	0	icmp	-	-	-	-	OTH	-	-	0	-	1	28	0	0	-
-#close	2020-10-14-18-47-51
+#close XXXX-XX-XX-XX-XX-XX

testing/btest/core/disable-mobile-ipv6.test

@@ -1,7 +1,9 @@
 # @TEST-REQUIRES: grep -q "#undef ENABLE_MOBILE_IPV6" $BUILD/zeek-config.h
 #
 # @TEST-EXEC: zeek -r $TRACES/mobile-ipv6/mip6_back.trace %INPUT
-# @TEST-EXEC: btest-diff weird.log
+# @TEST-EXEC: btest-diff unknown_protocols.log
+
+@load policy/misc/unknown-protocols
 
 event mobile_ipv6_message(p: pkt_hdr)
 	{

testing/btest/plugins/packet-protocol.zeek

@@ -1,6 +1,6 @@
-# @TEST-EXEC: zeek -r $TRACES/raw_layer.pcap
+# @TEST-EXEC: zeek -r $TRACES/raw_layer.pcap -e "@load policy/misc/unknown-protocols"
 # @TEST-EXEC: cat conn.log > output_orig
-# @TEST-EXEC: cat weird.log >> output_orig
+# @TEST-EXEC: cat unknown_protocols.log > output_orig
 # @TEST-EXEC: btest-diff output_orig
 # @TEST-EXEC: rm -f *.log
 #
@@ -12,13 +12,15 @@
 #
 # @TEST-EXEC: ZEEK_PLUGIN_PATH=`pwd` zeek -r $TRACES/raw_layer.pcap %INPUT > output_raw
 # @TEST-EXEC: cat conn.log >> output_raw
-# @TEST-EXEC: test ! -e weird.log
+# @TEST-EXEC: test ! -e unknown_protocols.log
 # @TEST-EXEC: btest-diff output_raw
 # @TEST-EXEC: rm -f *.log
 #
 # @TEST-EXEC: ZEEK_PLUGIN_PATH=`pwd` zeek -r $TRACES/raw_packets.trace %INPUT > output_llc
 # @TEST-EXEC: btest-diff output_llc
 
+@load policy/misc/unknown-protocols
+
 event raw_layer_message(msg: string, protocol: count)
 	{
 	print fmt("raw_layer_message (Message = '%s', Protocol = %x)", msg, protocol);
@@ -29,4 +31,3 @@ event llc_demo_message(dsap: count, ssap: count, control: count)
 	print fmt("llc_demo_message (DSAP = %x, SSAP = %x, Control = %x)",
 	 dsap, ssap, control);
 	}
-

testing/external/commit-hash.zeek-testing

@@ -1 +1 @@
-9611b9d06bef86c16a531e616972f7c9f5737da4
+a980aa1442f51a0c4e4af1061a04dc80038d3d04