diff --git a/NEWS b/NEWS index 9c420cf241..4d6e9cbcee 100644 --- a/NEWS +++ b/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 --------------------- diff --git a/doc b/doc index 2e5ef4b5a6..e6d31de9d8 160000 --- a/doc +++ b/doc @@ -1 +1 @@ -Subproject commit 2e5ef4b5a6752d53a4145b5b5b9da6f0bd4735a8 +Subproject commit e6d31de9d8f35815cfb0f5a361ca1fdbe3d443ed diff --git a/scripts/policy/misc/unknown-protocols.zeek b/scripts/policy/misc/unknown-protocols.zeek new file mode 100644 index 0000000000..000fc02107 --- /dev/null +++ b/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]); + } diff --git a/scripts/test-all-policy.zeek b/scripts/test-all-policy.zeek index 23dd9bc483..879d1fbd9b 100644 --- a/scripts/test-all-policy.zeek +++ b/scripts/test-all-policy.zeek @@ -1,7 +1,7 @@ # This file loads ALL policy scripts that are part of the Zeek distribution. -# +# # This is rarely makes sense, and is for testing only. -# +# # Note that we have a unit test that makes sure that all policy files shipped are # actually loaded here. If we have files that are part of the distribution yet # can't be loaded here, these must still be listed here with their load command @@ -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 diff --git a/src/Timer.cc b/src/Timer.cc index 85e0024da8..9fb0376323 100644 --- a/src/Timer.cc +++ b/src/Timer.cc @@ -47,6 +47,7 @@ const char* TimerNames[] = { "ParentProcessIDCheck", "TimerMgrExpireTimer", "ThreadHeartbeat", + "UnknownProtocolExpire", }; const char* timer_type_to_string(TimerType type) diff --git a/src/Timer.h b/src/Timer.h index e397f37f93..510102eddd 100644 --- a/src/Timer.h +++ b/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); diff --git a/src/event.bif b/src/event.bif index bf82df43f9..a6829b833f 100644 --- a/src/event.bif +++ b/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%); diff --git a/src/packet_analysis/Analyzer.cc b/src/packet_analysis/Analyzer.cc index 3d26d41a80..871e2c6e3f 100644 --- a/src/packet_analysis/Analyzer.cc +++ b/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; } diff --git a/src/packet_analysis/Manager.cc b/src/packet_analysis/Manager.cc index 54c6442f06..b95c60a972 100644 --- a/src/packet_analysis/Manager.cc +++ b/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; + + 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(len)); + + event_mgr.Enqueue(unknown_protocol, + make_intrusive(analyzer), + val_mgr->Count(protocol), + make_intrusive(bytes_len, (const char*) data)); + } + } + } diff --git a/src/packet_analysis/Manager.h b/src/packet_analysis/Manager.h index 6e9ddecb1c..e63d7422f4 100644 --- a/src/packet_analysis/Manager.h +++ b/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 analyzers; AnalyzerPtr root_analyzer = nullptr; uint64_t num_packets_processed = 0; detail::PacketProfiler* pkt_profiler = nullptr; + + using UnknownProtocolPair = std::pair; + std::map 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 diff --git a/testing/btest/Baseline/core.disable-mobile-ipv6/unknown_protocols.log b/testing/btest/Baseline/core.disable-mobile-ipv6/unknown_protocols.log new file mode 100644 index 0000000000..751352527d --- /dev/null +++ b/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 diff --git a/testing/btest/Baseline/coverage.find-bro-logs/out b/testing/btest/Baseline/coverage.find-bro-logs/out index c57889e881..aa85391f6e 100644 --- a/testing/btest/Baseline/coverage.find-bro-logs/out +++ b/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 diff --git a/testing/btest/Baseline/plugins.packet-protocol/output_build b/testing/btest/Baseline/plugins.packet-protocol/output_build index a5aa53185b..a8b9e8bc31 100644 --- a/testing/btest/Baseline/plugins.packet-protocol/output_build +++ b/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) diff --git a/testing/btest/Baseline/plugins.packet-protocol/output_llc b/testing/btest/Baseline/plugins.packet-protocol/output_llc index 2d25cc574d..90afbf2ca1 100644 --- a/testing/btest/Baseline/plugins.packet-protocol/output_llc +++ b/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) diff --git a/testing/btest/Baseline/plugins.packet-protocol/output_orig b/testing/btest/Baseline/plugins.packet-protocol/output_orig index 43883c192b..7a832e4072 100644 --- a/testing/btest/Baseline/plugins.packet-protocol/output_orig +++ b/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 -#open 2020-10-14-18-47-28 -#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.619112 CHhAvVGS1DHFjwGM9 172.22.214.60 8 192.0.78.212 0 icmp - - - - OTH - - 0 - 1 28 0 0 - -#close 2020-10-14-18-47-28 -#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 +#path unknown_protocols +#open XXXX-XX-XX-XX-XX-XX +#fields ts analyzer protocol_id first_bytes +#types time string string string +XXXXXXXXXX.XXXXXX ETHERNET 0x88b5 4920616d20656e636170 +#close XXXX-XX-XX-XX-XX-XX diff --git a/testing/btest/Baseline/plugins.packet-protocol/output_raw b/testing/btest/Baseline/plugins.packet-protocol/output_raw index 681ef7c770..f53ed99fa6 100644 --- a/testing/btest/Baseline/plugins.packet-protocol/output_raw +++ b/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 - -1599068759.619112 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 +XXXXXXXXXX.XXXXXX ClEkJM2Vm5giqnMf4h 172.22.214.60 8 192.0.78.150 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 XXXX-XX-XX-XX-XX-XX diff --git a/testing/btest/core/disable-mobile-ipv6.test b/testing/btest/core/disable-mobile-ipv6.test index eace575cca..3387ddf13c 100644 --- a/testing/btest/core/disable-mobile-ipv6.test +++ b/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) { diff --git a/testing/btest/plugins/packet-protocol.zeek b/testing/btest/plugins/packet-protocol.zeek index 4ac25356a0..ef70f0915b 100644 --- a/testing/btest/plugins/packet-protocol.zeek +++ b/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); } - diff --git a/testing/external/commit-hash.zeek-testing b/testing/external/commit-hash.zeek-testing index b79763a6b3..8a731e600a 100644 --- a/testing/external/commit-hash.zeek-testing +++ b/testing/external/commit-hash.zeek-testing @@ -1 +1 @@ -9611b9d06bef86c16a531e616972f7c9f5737da4 +a980aa1442f51a0c4e4af1061a04dc80038d3d04