Improvements to tcp rx path and debugging

- Increment rcv_nxt for fin packets
- Call tcp_segment_rcv only if buffer has data
- Parse rcv opts before deleting half-open connection
- Fix initial rcv_wnd
- Improved event logging

Change-Id: I9b83c04f432c4cec832c480b03e534deff02c3b1
Signed-off-by: Florin Coras <fcoras@cisco.com>

1 files changed, 185 insertions, 61 deletions

diff --git a/src/vnet/tcp/tcp_debug.h b/src/vnet/tcp/tcp_debug.h
index be51bca2a26..e3da56f4a43 100755
--- a/src/vnet/tcp/tcp_debug.h
+++ b/src/vnet/tcp/tcp_debug.h
@@ -19,10 +19,9 @@
 #include <vlib/vlib.h>
 
 #define TCP_DEBUG (1)
-#define TCP_DEBUG_SM (0)
-#define TCP_DEBUG_CC (1)
-#define TCP_DEBUG_CC_STAT (1)
-#define TCP_DEBUG_SM_VERBOSE (0)
+#define TCP_DEBUG_SM (2)
+#define TCP_DEBUG_CC (0)
+#define TCP_DEBUG_CC_STAT (0)
 
 #define foreach_tcp_dbg_evt		\
   _(INIT, "")				\
@@ -33,7 +32,9 @@
   _(UNBIND, "unbind")			\
   _(DELETE, "delete")			\
   _(SYN_SENT, "SYN sent")		\
-  _(SYN_RTX, "SYN retransmit")		\
+  _(SYNACK_SENT, "SYNACK sent")		\
+  _(SYNACK_RCVD, "SYNACK rcvd")		\
+  _(SYN_RXT, "SYN retransmit")		\
   _(FIN_SENT, "FIN sent")		\
   _(ACK_SENT, "ACK sent")		\
   _(DUPACK_SENT, "DUPACK sent")		\
@@ -43,6 +44,7 @@
   _(DUPACK_RCVD, "DUPACK rcvd")		\
   _(FIN_RCVD, "FIN rcvd")		\
   _(RST_RCVD, "RST rcvd")		\
+  _(STATE_CHANGE, "state change")	\
   _(PKTIZE, "packetize")		\
   _(INPUT, "in")			\
   _(SND_WND, "snd_wnd update")		\
@@ -96,11 +98,64 @@ typedef enum _tcp_dbg_evt
   ed = ELOG_TRACK_DATA (&vlib_global_main.elog_main,			\
 			_e, _tc->c_elog_track)
 
-#define TCP_EVT_INIT_HANDLER(_tc, _fmt, ...)				\
+#define TCP_DBG_IP_TAG_LCL(_tc)						\
 {									\
-  _tc->c_elog_track.name = 						\
-	(char *) format (0, _fmt, _tc->c_c_index, 0);			\
+  if (_tc->c_is_ip4)							\
+    {									\
+      ELOG_TYPE_DECLARE (_e) =						\
+      {									\
+        .format = "lcl: %d.%d.%d.%d:%d",				\
+        .format_args = "i4i4i4i4i4",					\
+      };								\
+      DECLARE_ETD(_tc, _e, 5);						\
+      ed->data[0] = _tc->c_lcl_ip.ip4.as_u8[0];				\
+      ed->data[1] = _tc->c_lcl_ip.ip4.as_u8[1];				\
+      ed->data[2] = _tc->c_lcl_ip.ip4.as_u8[2];				\
+      ed->data[3] = _tc->c_lcl_ip.ip4.as_u8[3];				\
+      ed->data[4] = clib_net_to_host_u16(_tc->c_lcl_port);		\
+    }									\
+}
+
+#define TCP_DBG_IP_TAG_RMT(_tc)						\
+{									\
+  if (_tc->c_is_ip4)							\
+    {									\
+      ELOG_TYPE_DECLARE (_e) =						\
+      {									\
+        .format = "rmt: %d.%d.%d.%d:%d",				\
+        .format_args = "i4i4i4i4i4",					\
+      };								\
+      DECLARE_ETD(_tc, _e, 5);						\
+      ed->data[0] = _tc->c_rmt_ip.ip4.as_u8[0];				\
+      ed->data[1] = _tc->c_rmt_ip.ip4.as_u8[1];				\
+      ed->data[2] = _tc->c_rmt_ip.ip4.as_u8[2];				\
+      ed->data[3] = _tc->c_rmt_ip.ip4.as_u8[3];				\
+      ed->data[4] = clib_net_to_host_u16(_tc->c_rmt_port);		\
+    }									\
+}
+
+#define TCP_EVT_INIT_HANDLER(_tc, _is_l, ...)				\
+{									\
+  char *_fmt = _is_l ? "l[%d].%d:%d%c" : "[%d].%d:%d->.%d:%d%c";	\
+  if (_tc->c_is_ip4)							\
+    {									\
+      _tc->c_elog_track.name =						\
+  	(char *) format (0, _fmt, _tc->c_thread_index, 			\
+			 _tc->c_lcl_ip.ip4.as_u8[3],			\
+			 clib_net_to_host_u16(_tc->c_lcl_port),		\
+			 _tc->c_rmt_ip.ip4.as_u8[3], 			\
+			 clib_net_to_host_u16(_tc->c_rmt_port), 0);	\
+    }									\
+  else									\
+      _tc->c_elog_track.name =						\
+	(char *) format (0, _fmt, _tc->c_thread_index, 			\
+			 _tc->c_lcl_ip.ip6.as_u8[15],			\
+			 clib_net_to_host_u16(_tc->c_lcl_port),		\
+			 _tc->c_rmt_ip.ip6.as_u8[15], 			\
+			 clib_net_to_host_u16(_tc->c_rmt_port), 0);	\
   elog_track_register (&vlib_global_main.elog_main, &_tc->c_elog_track);\
+  TCP_DBG_IP_TAG_LCL(_tc);						\
+  TCP_DBG_IP_TAG_RMT(_tc);						\
 }
 
 #define TCP_EVT_DEALLOC_HANDLER(_tc, ...)				\
@@ -110,7 +165,7 @@ typedef enum _tcp_dbg_evt
 
 #define TCP_EVT_OPEN_HANDLER(_tc, ...)					\
 {									\
-  TCP_EVT_INIT_HANDLER(_tc, "s%d%c");					\
+  TCP_EVT_INIT_HANDLER(_tc, 0);						\
   ELOG_TYPE_DECLARE (_e) =						\
   {									\
     .format = "open: index %d",						\
@@ -133,7 +188,7 @@ typedef enum _tcp_dbg_evt
 
 #define TCP_EVT_BIND_HANDLER(_tc, ...)					\
 {									\
-  TCP_EVT_INIT_HANDLER(_tc, "l%d%c");					\
+  TCP_EVT_INIT_HANDLER(_tc, 1);						\
   ELOG_TYPE_DECLARE (_e) =						\
   {									\
     .format = "bind: listener %d",					\
@@ -166,18 +221,6 @@ typedef enum _tcp_dbg_evt
   TCP_EVT_DEALLOC_HANDLER(_tc);						\
 }
 
-#define TCP_EVT_SYN_RCVD_HANDLER(_tc, ...)				\
-{									\
-  TCP_EVT_INIT_HANDLER(_tc, "s%d%c");					\
-  ELOG_TYPE_DECLARE (_e) =						\
-  {									\
-    .format = "SYNrx: irs %u",						\
-    .format_args = "i4",						\
-  };									\
-  DECLARE_ETD(_tc, _e, 1);						\
-  ed->data[0] = _tc->irs;						\
-}
-
 #define CONCAT_HELPER(_a, _b) _a##_b
 #define CC(_a, _b) CONCAT_HELPER(_a, _b)
 #define TCP_EVT_DBG(_evt, _args...) CC(_evt, _HANDLER)(_args)
@@ -190,63 +233,86 @@ typedef enum _tcp_dbg_evt
  */
 #if TCP_DEBUG_SM
 
-#define TCP_EVT_ACK_SENT_HANDLER(_tc, ...)				\
+#define TCP_EVT_STATE_CHANGE_HANDLER(_tc, ...)				\
 {									\
   ELOG_TYPE_DECLARE (_e) =						\
   {									\
-    .format = "ack_tx: acked %u rcv_nxt %u rcv_wnd %u snd_nxt %u snd_wnd %u",\
-    .format_args = "i4i4i4i4i4",					\
+    .format = "state: %s",						\
+    .format_args = "t4",						\
+    .n_enum_strings = 11,						\
+    .enum_strings = {                                           	\
+      "closed",	                                             		\
+      "listen",                                                 	\
+      "syn-sent",                                                 	\
+      "syn-rcvd",							\
+      "established",							\
+      "close_wait",							\
+      "fin-wait-1",							\
+      "last-ack",							\
+      "closing",							\
+      "fin-wait-2",							\
+      "time-wait",							\
+    },  								\
   };									\
-  DECLARE_ETD(_tc, _e, 5);						\
-  ed->data[0] = _tc->rcv_nxt - _tc->rcv_las;				\
-  ed->data[1] = _tc->rcv_nxt - _tc->irs;				\
-  ed->data[2] = _tc->rcv_wnd;						\
-  ed->data[3] = _tc->snd_nxt - _tc->iss;				\
-  ed->data[4] = _tc->snd_wnd;						\
+  DECLARE_ETD(_tc, _e, 1);						\
+  ed->data[0] = _tc->state;						\
 }
 
-#define TCP_EVT_DUPACK_SENT_HANDLER(_tc, ...)				\
+#define TCP_EVT_SYN_RCVD_HANDLER(_tc, ...)				\
 {									\
+  TCP_EVT_INIT_HANDLER(_tc, 0);						\
   ELOG_TYPE_DECLARE (_e) =						\
   {									\
-    .format = "dack_tx: rcv_nxt %u rcv_wnd %u snd_nxt %u av_wnd %u snd_wnd %u",\
-    .format_args = "i4i4i4i4i4",					\
+    .format = "syn-rx: irs %u",						\
+    .format_args = "i4",						\
   };									\
-  DECLARE_ETD(_tc, _e, 5);						\
-  ed->data[0] = _tc->rcv_nxt - _tc->irs;				\
-  ed->data[1] = _tc->rcv_wnd;						\
-  ed->data[2] = _tc->snd_nxt - _tc->iss;				\
-  ed->data[3] = tcp_available_wnd(_tc);					\
-  ed->data[4] = _tc->snd_wnd;						\
+  DECLARE_ETD(_tc, _e, 1);						\
+  ed->data[0] = _tc->irs;						\
+  TCP_EVT_STATE_CHANGE_HANDLER(_tc);					\
 }
 
 #define TCP_EVT_SYN_SENT_HANDLER(_tc, ...)				\
 {									\
   ELOG_TYPE_DECLARE (_e) =						\
   {									\
-    .format = "SYNtx: iss %u",						\
+    .format = "syn-tx: iss %u",						\
     .format_args = "i4",						\
   };									\
   DECLARE_ETD(_tc, _e, 1);						\
   ed->data[0] = _tc->iss;						\
+  TCP_EVT_STATE_CHANGE_HANDLER(_tc);					\
 }
 
-#define TCP_EVT_SYN_RTX_HANDLER(_tc, ...)				\
+#define TCP_EVT_SYNACK_SENT_HANDLER(_tc, ...)				\
 {									\
   ELOG_TYPE_DECLARE (_e) =						\
   {									\
-    .format = "SYNrtx: iss %u",						\
-    .format_args = "i4",						\
+    .format = "synack-tx: iss %u irs %u",				\
+    .format_args = "i4i4",						\
   };									\
-  DECLARE_ETD(_tc, _e, 1);						\
+  DECLARE_ETD(_tc, _e, 2);						\
+  ed->data[0] = _tc->iss;						\
+  ed->data[1] = _tc->irs;						\
+}
+
+#define TCP_EVT_SYNACK_RCVD_HANDLER(_tc, ...)				\
+{									\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "synack-rx: iss %u irs %u",				\
+    .format_args = "i4i4",						\
+  };									\
+  DECLARE_ETD(_tc, _e, 2);						\
   ed->data[0] = _tc->iss;						\
+  ed->data[1] = _tc->irs;						\
+  TCP_EVT_STATE_CHANGE_HANDLER(_tc);					\
 }
 
 #define TCP_EVT_FIN_SENT_HANDLER(_tc, ...)				\
 {									\
   ELOG_TYPE_DECLARE (_e) =						\
   {									\
-    .format = "FINtx: snd_nxt %d rcv_nxt %d",				\
+    .format = "fin-tx: snd_nxt %d rcv_nxt %d",				\
     .format_args = "i4i4",						\
   };									\
   DECLARE_ETD(_tc, _e, 2);						\
@@ -258,19 +324,20 @@ typedef enum _tcp_dbg_evt
 {									\
   ELOG_TYPE_DECLARE (_e) =						\
   {									\
-    .format = "RSTtx: snd_nxt %d rcv_nxt %d",				\
+    .format = "rst-tx: snd_nxt %d rcv_nxt %d",				\
     .format_args = "i4i4",						\
   };									\
   DECLARE_ETD(_tc, _e, 2);						\
   ed->data[0] = _tc->snd_nxt - _tc->iss;				\
   ed->data[1] = _tc->rcv_nxt - _tc->irs;				\
+  TCP_EVT_STATE_CHANGE_HANDLER(_tc);					\
 }
 
 #define TCP_EVT_FIN_RCVD_HANDLER(_tc, ...)				\
 {									\
   ELOG_TYPE_DECLARE (_e) =						\
   {									\
-    .format = "FINrx: snd_nxt %d rcv_nxt %d",				\
+    .format = "fin-rx: snd_nxt %d rcv_nxt %d",				\
     .format_args = "i4i4",						\
   };									\
   DECLARE_ETD(_tc, _e, 2);						\
@@ -282,7 +349,7 @@ typedef enum _tcp_dbg_evt
 {									\
   ELOG_TYPE_DECLARE (_e) =						\
   {									\
-    .format = "RSTrx: snd_nxt %d rcv_nxt %d",				\
+    .format = "rst-rx: snd_nxt %d rcv_nxt %d",				\
     .format_args = "i4i4",						\
   };									\
   DECLARE_ETD(_tc, _e, 2);						\
@@ -290,6 +357,67 @@ typedef enum _tcp_dbg_evt
   ed->data[1] = _tc->rcv_nxt - _tc->irs;				\
 }
 
+#define TCP_EVT_SYN_RXT_HANDLER(_tc, _type, ...)			\
+{									\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "%s-rxt: iss %u",						\
+    .format_args = "t4i4",						\
+    .n_enum_strings = 2,						\
+    .enum_strings = {                                           	\
+	"syn",	                                             		\
+        "syn-ack",							\
+    },  								\
+  };									\
+  DECLARE_ETD(_tc, _e, 2);						\
+  ed->data[0] = _type;							\
+  ed->data[1] = _tc->iss;						\
+}
+
+#else
+#define TCP_EVT_SYN_SENT_HANDLER(_tc, ...)
+#define TCP_EVT_SYNACK_SENT_HANDLER(_tc, ...)
+#define TCP_EVT_SYNACK_RCVD_HANDLER(_tc, ...)
+#define TCP_EVT_SYN_RXT_HANDLER(_tc, ...)
+#define TCP_EVT_FIN_SENT_HANDLER(_tc, ...)
+#define TCP_EVT_RST_SENT_HANDLER(_tc, ...)
+#define TCP_EVT_FIN_RCVD_HANDLER(_tc, ...)
+#define TCP_EVT_RST_RCVD_HANDLER(_tc, ...)
+#define TCP_EVT_STATE_CHANGE_HANDLER(_tc, ...)
+#endif
+
+#if TCP_DEBUG_SM > 1
+
+#define TCP_EVT_ACK_SENT_HANDLER(_tc, ...)				\
+{									\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "ack-tx: acked %u rcv_nxt %u rcv_wnd %u snd_nxt %u snd_wnd %u",\
+    .format_args = "i4i4i4i4i4",					\
+  };									\
+  DECLARE_ETD(_tc, _e, 5);						\
+  ed->data[0] = _tc->rcv_nxt - _tc->rcv_las;				\
+  ed->data[1] = _tc->rcv_nxt - _tc->irs;				\
+  ed->data[2] = _tc->rcv_wnd;						\
+  ed->data[3] = _tc->snd_nxt - _tc->iss;				\
+  ed->data[4] = _tc->snd_wnd;						\
+}
+
+#define TCP_EVT_DUPACK_SENT_HANDLER(_tc, ...)				\
+{									\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "dack-tx: rcv_nxt %u rcv_wnd %u snd_nxt %u av_wnd %u snd_wnd %u",\
+    .format_args = "i4i4i4i4i4",					\
+  };									\
+  DECLARE_ETD(_tc, _e, 5);						\
+  ed->data[0] = _tc->rcv_nxt - _tc->irs;				\
+  ed->data[1] = _tc->rcv_wnd;						\
+  ed->data[2] = _tc->snd_nxt - _tc->iss;				\
+  ed->data[3] = tcp_available_wnd(_tc);					\
+  ed->data[4] = _tc->snd_wnd;						\
+}
+
 #define TCP_EVT_ACK_RCVD_HANDLER(_tc, ...)				\
 {									\
   ELOG_TYPE_DECLARE (_e) =						\
@@ -309,7 +437,7 @@ typedef enum _tcp_dbg_evt
 {									\
   ELOG_TYPE_DECLARE (_e) =						\
   {									\
-    .format = "dack_rx: snd_una %u cwnd %u snd_wnd %u flight %u rcv_wnd %u",\
+    .format = "dack-rx: snd_una %u cwnd %u snd_wnd %u flight %u rcv_wnd %u",\
     .format_args = "i4i4i4i4i4",					\
   };									\
   DECLARE_ETD(_tc, _e, 5);						\
@@ -370,7 +498,7 @@ typedef enum _tcp_dbg_evt
     }                                                           	\
   ELOG_TYPE_DECLARE (_e) =                                      	\
   {                                                             	\
-    .format = "TimerPop: %s (%d)",                              	\
+    .format = "timer-pop: %s (%d)",                              	\
     .format_args = "t4i4",                                      	\
     .n_enum_strings = 7,                                        	\
     .enum_strings = {                                           	\
@@ -391,7 +519,8 @@ typedef enum _tcp_dbg_evt
     }									\
   else									\
     {									\
-      clib_warning ("pop for unexisting connection %d", _tc_index);	\
+      clib_warning ("pop %d for unexisting connection %d", _timer_id,	\
+		    _tc_index);						\
     }									\
 }
 
@@ -414,7 +543,7 @@ typedef enum _tcp_dbg_evt
 {									\
   ELOG_TYPE_DECLARE (_e) =						\
   {									\
-    .format = "paws fail: seq %u end %u tsval %u tsval_recent %u",	\
+    .format = "paws-err: seq %u end %u tsval %u tsval_recent %u",	\
     .format_args = "i4i4i4i4",						\
   };									\
   DECLARE_ETD(_tc, _e, 4);						\
@@ -465,12 +594,6 @@ if (_av > 0) 								\
 #else
 #define TCP_EVT_ACK_SENT_HANDLER(_tc, ...)
 #define TCP_EVT_DUPACK_SENT_HANDLER(_tc, ...)
-#define TCP_EVT_SYN_SENT_HANDLER(_tc, ...)
-#define TCP_EVT_SYN_RTX_HANDLER(_tc, ...)
-#define TCP_EVT_FIN_SENT_HANDLER(_tc, ...)
-#define TCP_EVT_RST_SENT_HANDLER(_tc, ...)
-#define TCP_EVT_FIN_RCVD_HANDLER(_tc, ...)
-#define TCP_EVT_RST_RCVD_HANDLER(_tc, ...)
 #define TCP_EVT_ACK_RCVD_HANDLER(_tc, ...)
 #define TCP_EVT_DUPACK_RCVD_HANDLER(_tc, ...)
 #define TCP_EVT_PKTIZE_HANDLER(_tc, ...)
@@ -485,12 +608,12 @@ if (_av > 0) 								\
 /*
  * State machine verbose
  */
-#if TCP_DBG_SM_VERBOSE
+#if TCP_DEBUG_SM > 2
 #define TCP_EVT_SND_WND_HANDLER(_tc, ...)				\
 {									\
   ELOG_TYPE_DECLARE (_e) =						\
   {									\
-    .format = "snd_wnd update: %u ",					\
+    .format = "snd-wnd update: %u ",					\
     .format_args = "i4",						\
   };									\
   DECLARE_ETD(_tc, _e, 1);						\
@@ -617,6 +740,7 @@ if (_tc->c_cc_stat_tstamp + STATS_INTERVAL < tcp_time_now())		\
 #define TCP_EVT_CC_RTX_HANDLER(_tc, offset, n_bytes, ...)
 #define TCP_EVT_CC_EVT_HANDLER(_tc, _sub_evt, ...)
 #define TCP_EVT_CC_PACK_HANDLER(_tc, ...)
+#define TCP_EVT_CC_STAT_HANDLER(_tc, ...)
 #endif
 
 #endif /* SRC_VNET_TCP_TCP_DEBUG_H_ */