Merge remote-tracking branch 'origin/topic/vern/perf-history'

* origin/topic/vern/perf-history:
  only generate history threshold events for > 1 instance mention those events in NEWS
  a different sort of history update
  'W' for zero window implemented; logarithmic 'T'/'C'/'W' history repetitions

I reverted a change that made TCP window tracking unconditional (possibly
accepting out-of-order packets) until further verification of test suite
changes.

CHANGES

@@ -1,4 +1,12 @@
 
+2.5-796 | 2018-08-01 16:31:25 -0500
+
+  * Add 'W' connection history indicator for zero windows
+    (Vern Paxson, Corelight)
+  
+  * Allow logarithmic 'T'/'C'/'W' connection history repetitions, which
+    also now raise their own events (Vern Paxson, Corelight)
+
 2.5-792 | 2018-08-01 12:15:31 -0500
 
   * fix NTLM NegotiateFlags field offsets (Jeffrey Bencteux)

NEWS

@@ -279,6 +279,27 @@ New Functionality
 
 - Bro now supports OpenSSL 1.1.
 
+- The new connection/conn.log history character 'W' indicates that
+  the originator ('w' = responder) advertised a TCP zero window
+  (instructing the peer to not send any data until receiving a
+  non-zero window).
+
+- The connection/conn.log history characters 'C' (checksum error seen),
+  'T' (retransmission seen), and 'W' (zero window advertised) are now
+  repeated in a logarithmic fashion upon seeing multiple instances
+  of the corresponding behavior.  Thus a connection with 2 C's in its
+  history means that the originator sent >= 10 packets with checksum
+  errors; 3 C's means >= 100, etc.
+
+- The above connection history behaviors occurring multiple times
+  (i.e., starting at 10 instances, than again for 100 instances,
+  etc.) generate corresponding events: tcp_multiple_checksum_errors,
+  udp_multiple_checksum_errors, tcp_multiple_zero_windows, and
+  tcp_multiple_retransmissions.  Each has the same form, e.g.
+
+      event tcp_multiple_retransmissions(c: connection, is_orig: bool,
+				                         threshold: count);
+
 Changed Functionality
 ---------------------
 

VERSION

@@ -1 +1 @@
-2.5-792
+2.5-796

doc/intro/index.rst

@@ -169,7 +169,7 @@ History
 
 Bro's history goes back much further than many people realize. `Vern
 Paxson <http://www.icir.org/vern>`_ designed and implemented the
-initial version almost two decades ago.
+initial version more than two decades ago.
 Vern began work on the code in 1995 as a researcher at the `Lawrence
 Berkeley National Laboratory (LBNL) <http://www.lbl.gov>`_. Berkeley
 Lab began operational deployment in 1996, and the USENIX Security

scripts/base/protocols/conn/main.bro

@@ -86,8 +86,9 @@ export {
 		## d       packet with payload ("data")
 		## f       packet with FIN bit set
 		## r       packet with RST bit set
-		## c       packet with a bad checksum
+		## c       packet with a bad checksum (applies to UDP too)
 		## t       packet with retransmitted payload
+		## w       packet with a zero window advertisement
 		## i       inconsistent packet (e.g. FIN+RST bits set)
 		## q       multi-flag packet (SYN+FIN or SYN+RST bits set)
 		## ^       connection direction was flipped by Bro's heuristic
@@ -95,12 +96,15 @@ export {
 		##
 		## If the event comes from the originator, the letter is in
 		## upper-case; if it comes from the responder, it's in
-		## lower-case.  The 'a', 'c', 'd', 'i', 'q', and 't' flags are
+		## lower-case.  The 'a', 'd', 'i' and 'q' flags are
 		## recorded a maximum of one time in either direction regardless
-		## of how many are actually seen.  However, 'f', 'h', 'r', or
-		## 's' may be recorded multiple times for either direction and
-		## only compressed when sharing a sequence number with the
+		## of how many are actually seen.  'f', 'h', 'r' and
+		## 's' can be recorded multiple times for either direction
+		## if the associated sequence number differs from the
 		## last-seen packet of the same flag type.
+		## 'c', 't' and 'w' are recorded in a logarithmic fashion:
+		## the second instance represents that the event was seen
+		## (at least) 10 times; the third instance, 100 times; etc.
 		history:      string          &log &optional;
 		## Number of packets that the originator sent.
 		## Only set if :bro:id:`use_conn_size_analyzer` = T.

src/Conn.cc

@@ -289,6 +289,50 @@ bool Connection::IsReuse(double t, const u_char* pkt)
 	return root_analyzer && root_analyzer->IsReuse(t, pkt);
 	}
 
+bool Connection::ScaledHistoryEntry(char code, uint32& counter,
+                                    uint32& scaling_threshold,
+                                    uint32 scaling_base)
+	{
+	if ( ++counter == scaling_threshold )
+		{
+		AddHistory(code);
+
+		auto new_threshold = scaling_threshold * scaling_base;
+
+		if ( new_threshold <= scaling_threshold )
+			// This can happen due to wrap-around.  In that
+			// case, reset the counter but leave the threshold
+			// unchanged.
+			counter = 0;
+
+		else
+			scaling_threshold = new_threshold;
+
+		return true;
+		}
+
+	return false;
+	}
+
+void Connection::HistoryThresholdEvent(EventHandlerPtr e, bool is_orig,
+                                       uint32 threshold)
+	{
+	if ( ! e )
+		return;
+
+	if ( threshold == 1 )
+		// This will be far and away the most common case,
+		// and at this stage it's not a *multiple* instance.
+		return;
+
+	val_list* vl = new val_list;
+	vl->append(BuildConnVal());
+	vl->append(new Val(is_orig, TYPE_BOOL));
+	vl->append(new Val(threshold, TYPE_COUNT));
+
+	ConnectionEvent(e, 0, vl);
+	}
+
 void Connection::DeleteTimer(double /* t */)
 	{
 	if ( is_active )

src/Conn.h

@@ -240,6 +240,17 @@ public:
 			return true;
 		}
 
+	// Increments the passed counter and adds it as a history
+	// code if it has crossed the next scaling threshold.  Scaling
+	// is done in terms of powers of the third argument.
+	// Returns true if the threshold was crossed, false otherwise.
+	bool ScaledHistoryEntry(char code, uint32& counter,
+	                        uint32& scaling_threshold,
+	                        uint32 scaling_base = 10);
+
+	void HistoryThresholdEvent(EventHandlerPtr e, bool is_orig,
+	                           uint32 threshold);
+
 	void AddHistory(char code)	{ history += code; }
 
 	void DeleteTimer(double t);

src/analyzer/protocol/tcp/TCP.cc

@@ -459,7 +459,7 @@ bool TCP_Analyzer::ValidateChecksum(const struct tcphdr* tp,
 	     ! endpoint->ValidChecksum(tp, len) )
 		{
 		Weird("bad_TCP_checksum");
-		endpoint->CheckHistory(HIST_CORRUPT_PKT, 'C');
+		endpoint->ChecksumError();
 		return false;
 		}
 	else
@@ -579,16 +579,38 @@ static void init_window(TCP_Endpoint* endpoint, TCP_Endpoint* peer,
 static void update_window(TCP_Endpoint* endpoint, unsigned int window,
                           uint32 base_seq, uint32 ack_seq, TCP_Flags flags)
 	{
-	// Note, the offered window on an initial SYN is unscaled, even
-	// if the SYN includes scaling, so we need to do the following
-	// test *before* updating the scaling information below.  (Hmmm,
-	// how does this work for windows on SYN/ACKs? ###)
+	// Note, applying scaling here would be incorrect for an initial SYN,
+	// whose window value is always unscaled.  However, we don't
+	// check the window's value for recision in that case anyway, so
+	// no-harm-no-foul.
 	int scale = endpoint->window_scale;
 	window = window << scale;
 
+	// Zero windows are boring if either (1) they come with a RST packet
+	// or after a RST packet, or (2) they come after the peer has sent
+	// a FIN (because there's no relevant window at that point anyway).
+	// (They're also boring if they come after the peer has sent a RST,
+	// but *nothing* should be sent in response to a RST, so we ignore
+	// that case.)
+	//
+	// However, they *are* potentially interesting if sent by an
+	// endpoint that's already sent a FIN, since that FIN meant "I'm
+	// not going to send any more", but doesn't mean "I won't receive
+	// any more".
+	if ( window == 0 && ! flags.RST() &&
+	     endpoint->peer->state != TCP_ENDPOINT_CLOSED &&
+	     endpoint->state != TCP_ENDPOINT_RESET )
+		endpoint->ZeroWindow();
+
 	// Don't analyze window values off of SYNs, they're sometimes
-	// immediately rescinded.
-	if ( ! flags.SYN() )
+	// immediately rescinded.  Also don't do so for FINs or RSTs,
+	// or if the connection has already been partially closed, since
+	// such recisions occur frequently in practice, probably as the
+	// receiver loses buffer memory due to its process going away.
+
+	if ( ! flags.SYN() && ! flags.FIN() && ! flags.RST() &&
+	     endpoint->state != TCP_ENDPOINT_CLOSED &&
+	     endpoint->state != TCP_ENDPOINT_RESET )
 		{
 		// ### Decide whether to accept new window based on Active
 		// Mapping policy.
@@ -601,21 +623,12 @@ static void update_window(TCP_Endpoint* endpoint, unsigned int window,
 
 			if ( advance < 0 )
 				{
-				// A window recision.  We don't report these
-				// for FINs or RSTs, or if the connection
-				// has already been partially closed, since
-				// such recisions occur frequently in practice,
-				// probably as the receiver loses buffer memory
-				// due to its process going away.
-				//
-				// We also, for window scaling, allow a bit
-				// of slop ###.  This is because sometimes
-				// there will be an apparent recision due
-				// to the granularity of the scaling.
-				if ( ! flags.FIN() && ! flags.RST() &&
-				     endpoint->state != TCP_ENDPOINT_CLOSED &&
-				     endpoint->state != TCP_ENDPOINT_RESET &&
-				     (-advance) >= (1 << scale) )
+				// An apparent window recision.  Allow a
+				// bit of slop for window scaling.  This is
+				// because sometimes there will be an
+				// apparent recision due to the granularity
+				// of the scaling.
+				if ( (-advance) >= (1 << scale) )
 					endpoint->Conn()->Weird("window_recision");
 				}
 
@@ -1206,7 +1219,7 @@ static int32 update_last_seq(TCP_Endpoint* endpoint, uint32 last_seq,
 		endpoint->UpdateLastSeq(last_seq);
 
 	else if ( delta_last < 0 && len > 0 )
-		endpoint->CheckHistory(HIST_RXMIT, 'T');
+		endpoint->DidRxmit();
 
 	return delta_last;
 	}

src/analyzer/protocol/tcp/TCP_Endpoint.cc

@@ -32,6 +32,9 @@ TCP_Endpoint::TCP_Endpoint(TCP_Analyzer* arg_analyzer, int arg_is_orig)
 	tcp_analyzer = arg_analyzer;
 	is_orig = arg_is_orig;
 
+	chk_cnt = rxmt_cnt = win0_cnt = 0;
+	chk_thresh = rxmt_thresh = win0_thresh = 1;
+
 	hist_last_SYN = hist_last_FIN = hist_last_RST = 0;
 
 	src_addr = is_orig ? Conn()->RespAddr() : Conn()->OrigAddr();
@@ -284,3 +287,29 @@ void TCP_Endpoint::AddHistory(char code)
 	Conn()->AddHistory(code);
 	}
 
+void TCP_Endpoint::ChecksumError()
+	{
+	uint32 t = chk_thresh;
+	if ( Conn()->ScaledHistoryEntry(IsOrig() ? 'C' : 'c',
+	                                chk_cnt, chk_thresh) )
+		Conn()->HistoryThresholdEvent(tcp_multiple_checksum_errors,
+		                              IsOrig(), t);
+	}
+
+void TCP_Endpoint::DidRxmit()
+	{
+	uint32 t = rxmt_thresh;
+	if ( Conn()->ScaledHistoryEntry(IsOrig() ? 'T' : 't',
+	                                rxmt_cnt, rxmt_thresh) )
+		Conn()->HistoryThresholdEvent(tcp_multiple_retransmissions,
+		                              IsOrig(), t);
+	}
+
+void TCP_Endpoint::ZeroWindow()
+	{
+	uint32 t = win0_thresh;
+	if ( Conn()->ScaledHistoryEntry(IsOrig() ? 'W' : 'w',
+	                                win0_cnt, win0_thresh) )
+		Conn()->HistoryThresholdEvent(tcp_multiple_zero_windows,
+		                              IsOrig(), t);
+	}

src/analyzer/protocol/tcp/TCP_Endpoint.h

@@ -166,6 +166,15 @@ public:
 
 	int ValidChecksum(const struct tcphdr* tp, int len) const;
 
+	// Called to inform endpoint that it has generated a checksum error.
+	void ChecksumError();
+
+	// Called to inform endpoint that it has generated a retransmission.
+	void DidRxmit();
+
+	// Called to inform endpoint that it has offered a zero window.
+	void ZeroWindow();
+
 	// Returns true if the data was used (and hence should be recorded
 	// in the save file), false otherwise.
 	int DataSent(double t, uint64 seq, int len, int caplen, const u_char* data,
@@ -188,6 +197,7 @@ public:
 #define HIST_MULTI_FLAG_PKT 0x40
 #define HIST_CORRUPT_PKT 0x80
 #define HIST_RXMIT 0x100
+#define HIST_WIN0 0x200
 	int CheckHistory(uint32 mask, char code);
 	void AddHistory(char code);
 
@@ -202,7 +212,7 @@ public:
 	double start_time, last_time;
 	IPAddr src_addr; // the other endpoint
 	IPAddr dst_addr; // this endpoint
-	uint32 window; // current congestion window (*scaled*, not pre-scaling)
+	uint32 window; // current advertised window (*scaled*, not pre-scaling)
 	int window_scale;  // from the TCP option
 	uint32 window_ack_seq; // at which ack_seq number did we record 'window'
 	uint32 window_seq; // at which sending sequence number did we record 'window'
@@ -225,6 +235,11 @@ protected:
 	uint32 last_seq, ack_seq;	// in host order
 	uint32 seq_wraps, ack_wraps;	// Number of times 32-bit TCP sequence space
 					// has wrapped around (overflowed).
+
+	// Performance history accounting.
+	uint32 chk_cnt, chk_thresh;
+	uint32 rxmt_cnt, rxmt_thresh;
+	uint32 win0_cnt, win0_thresh;
 };
 
 #define ENDIAN_UNKNOWN 0

src/analyzer/protocol/tcp/events.bif

@@ -290,6 +290,43 @@ event tcp_contents%(c: connection, is_orig: bool, seq: count, contents: string%)
 ## TODO.
 event tcp_rexmit%(c: connection, is_orig: bool, seq: count, len: count, data_in_flight: count, window: count%);
 
+## Generated if a TCP flow crosses a checksum-error threshold, per
+## 'C'/'c' history reporting.
+##
+## c: The connection record for the TCP connection.
+##
+## is_orig: True if the event is raised for the originator side.
+##
+## threshold: the threshold that was crossed
+##
+## .. bro:see::  udp_multiple_checksum_errors
+##    tcp_multiple_zero_windows tcp_multiple_retransmissions
+event tcp_multiple_checksum_errors%(c: connection, is_orig: bool, threshold: count%);
+
+## Generated if a TCP flow crosses a zero-window threshold, per
+## 'W'/'w' history reporting.
+##
+## c: The connection record for the TCP connection.
+##
+## is_orig: True if the event is raised for the originator side.
+##
+## threshold: the threshold that was crossed
+##
+## .. bro:see::  tcp_multiple_checksum_errors tcp_multiple_retransmissions
+event tcp_multiple_zero_windows%(c: connection, is_orig: bool, threshold: count%);
+
+## Generated if a TCP flow crosses a retransmission threshold, per
+## 'T'/'t' history reporting.
+##
+## c: The connection record for the TCP connection.
+##
+## is_orig: True if the event is raised for the originator side.
+##
+## threshold: the threshold that was crossed
+##
+## .. bro:see::  tcp_multiple_checksum_errors tcp_multiple_zero_windows
+event tcp_multiple_retransmissions%(c: connection, is_orig: bool, threshold: count%);
+
 ## Generated when failing to write contents of a TCP stream to a file.
 ##
 ## c: The connection whose contents are being recorded.

src/analyzer/protocol/udp/UDP.cc

@@ -20,6 +20,9 @@ UDP_Analyzer::UDP_Analyzer(Connection* conn)
 	conn->EnableStatusUpdateTimer();
 	conn->SetInactivityTimeout(udp_inactivity_timeout);
 	request_len = reply_len = -1;	// -1 means "haven't seen any activity"
+
+	req_chk_cnt = rep_chk_cnt = 0;
+	req_chk_thresh = rep_chk_thresh = 1;
 	}
 
 UDP_Analyzer::~UDP_Analyzer()
@@ -77,9 +80,19 @@ void UDP_Analyzer::DeliverPacket(int len, const u_char* data, bool is_orig,
 			Weird("bad_UDP_checksum");
 
 			if ( is_orig )
-				Conn()->CheckHistory(HIST_ORIG_CORRUPT_PKT, 'C');
+				{
+				uint32 t = req_chk_thresh;
+				if ( Conn()->ScaledHistoryEntry('C', req_chk_cnt,
+				                                req_chk_thresh) )
+					ChecksumEvent(is_orig, t);
+				}
 			else
-				Conn()->CheckHistory(HIST_RESP_CORRUPT_PKT, 'c');
+				{
+				uint32 t = rep_chk_thresh;
+				if ( Conn()->ScaledHistoryEntry('c', rep_chk_cnt,
+				                                rep_chk_thresh) )
+					ChecksumEvent(is_orig, t);
+				}
 
 			return;
 			}
@@ -209,6 +222,12 @@ unsigned int UDP_Analyzer::MemoryAllocation() const
 	return Analyzer::MemoryAllocation() + padded_sizeof(*this) - 24;
 	}
 
+void UDP_Analyzer::ChecksumEvent(bool is_orig, uint32 threshold)
+	{
+	Conn()->HistoryThresholdEvent(udp_multiple_checksum_errors,
+	                              is_orig, threshold);
+	}
+
 bool UDP_Analyzer::ValidateChecksum(const IP_Hdr* ip, const udphdr* up, int len)
 	{
 	uint32 sum;

src/analyzer/protocol/udp/UDP.h

@@ -31,6 +31,8 @@ protected:
 	bool IsReuse(double t, const u_char* pkt) override;
 	unsigned int MemoryAllocation() const override;
 
+	void ChecksumEvent(bool is_orig, uint32 threshold);
+
 	// Returns true if the checksum is valid, false if not
 	static bool ValidateChecksum(const IP_Hdr* ip, const struct udphdr* up,
 	                             int len);
@@ -44,6 +46,10 @@ private:
 #define HIST_RESP_DATA_PKT 0x2
 #define HIST_ORIG_CORRUPT_PKT 0x4
 #define HIST_RESP_CORRUPT_PKT 0x8
+
+	// For tracking checksum history.
+	uint32 req_chk_cnt, req_chk_thresh;
+	uint32 rep_chk_cnt, rep_chk_thresh;
 };
 
 } } // namespace analyzer::* 

src/analyzer/protocol/udp/events.bif

@@ -36,3 +36,16 @@ event udp_reply%(u: connection%);
 ##    udp_content_deliver_all_orig udp_content_deliver_all_resp
 ##    udp_content_delivery_ports_orig udp_content_delivery_ports_resp
 event udp_contents%(u: connection, is_orig: bool, contents: string%);
+
+## Generated if a UDP flow crosses a checksum-error threshold, per
+## 'C'/'c' history reporting.
+##
+## u: The connection record for the corresponding UDP flow.
+##
+## is_orig: True if the event is raised for the originator side.
+##
+## threshold: the threshold that was crossed
+##
+## .. bro:see::  udp_reply udp_request udp_session_done
+##    tcp_multiple_checksum_errors
+event udp_multiple_checksum_errors%(u: connection, is_orig: bool, threshold: count%);

testing/btest/Baseline/core.pppoe-over-qinq/conn.log

@@ -3,8 +3,8 @@
 #empty_field	(empty)
 #unset_field	-
 #path	conn
-#open	2018-07-06-12-25-54
+#open	2018-08-01-20-09-03
 #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]
-1523351398.449222	CHhAvVGS1DHFjwGM9	1.1.1.1	20394	2.2.2.2	443	tcp	-	273.626833	11352	4984	SF	-	-	0	ShADdtaTFf	44	25283	42	13001	-
-#close	2018-07-06-12-25-54
+1523351398.449222	CHhAvVGS1DHFjwGM9	1.1.1.1	20394	2.2.2.2	443	tcp	-	273.626833	11352	4984	SF	-	-	0	ShADdtaTTFf	44	25283	42	13001	-
+#close	2018-08-01-20-09-03