VPP-659 Improve tcp/session debugging and testing

- event-logging support for tcp and session layer
- improvements to uri test code
- builtin_server on port 1234
- use the CLOSEWAIT timer when we rx FIN in FIN_WAIT_2 state

Change-Id: Ibc445f164b2086b20323bf89c77cffd3059f570f
Signed-off-by: Florin Coras <fcoras@cisco.com>
Signed-off-by: Dave Barach <dbarach@cisco.com>
Signed-off-by: Dave Barach <dave@barachs.net>

6 files changed, 485 insertions, 130 deletions

diff --git a/src/vnet/tcp/builtin_server.c b/src/vnet/tcp/builtin_server.c
index 9b697a01d5f..dd6759c56e0 100644
--- a/src/vnet/tcp/builtin_server.c
+++ b/src/vnet/tcp/builtin_server.c
@@ -160,7 +160,7 @@ server_create (vlib_main_t * vm)
   memset (a, 0, sizeof (*a));
   memset (options, 0, sizeof (options));
 
-  a->uri = "tcp://0.0.0.0/80";
+  a->uri = "tcp://0.0.0.0/1234";
   a->api_client_index = ~0;
   a->session_cb_vft = &builtin_session_cb_vft;
   a->options = options;
diff --git a/src/vnet/tcp/tcp.c b/src/vnet/tcp/tcp.c
index d2df5c3eae0..0d2e6d0e91a 100644
--- a/src/vnet/tcp/tcp.c
+++ b/src/vnet/tcp/tcp.c
@@ -21,7 +21,7 @@
 tcp_main_t tcp_main;
 
 static u32
-tcp_connection_bind (vlib_main_t * vm, u32 session_index, ip46_address_t * ip,
+tcp_connection_bind (u32 session_index, ip46_address_t * ip,
 		     u16 port_host_byte_order, u8 is_ip4)
 {
   tcp_main_t *tm = &tcp_main;
@@ -43,42 +43,41 @@ tcp_connection_bind (vlib_main_t * vm, u32 session_index, ip46_address_t * ip,
   listener->state = TCP_STATE_LISTEN;
   listener->c_is_ip4 = 1;
 
+  tcp_connection_timers_init (listener);
+
+  TCP_EVT_DBG (TCP_EVT_BIND, listener);
+
   return listener->c_c_index;
 }
 
 u32
-tcp_session_bind_ip4 (vlib_main_t * vm, u32 session_index,
-		      ip46_address_t * ip, u16 port_host_byte_order)
+tcp_session_bind_ip4 (u32 session_index, ip46_address_t * ip,
+		      u16 port_host_byte_order)
 {
-  return tcp_connection_bind (vm, session_index, ip, port_host_byte_order, 1);
+  return tcp_connection_bind (session_index, ip, port_host_byte_order, 1);
 }
 
 u32
-tcp_session_bind_ip6 (vlib_main_t * vm, u32 session_index,
-		      ip46_address_t * ip, u16 port_host_byte_order)
+tcp_session_bind_ip6 (u32 session_index, ip46_address_t * ip,
+		      u16 port_host_byte_order)
 {
-  return tcp_connection_bind (vm, session_index, ip, port_host_byte_order, 0);
+  return tcp_connection_bind (session_index, ip, port_host_byte_order, 0);
 
 }
 
 static void
-tcp_session_unbind (u32 listener_index)
+tcp_connection_unbind (u32 listener_index)
 {
   tcp_main_t *tm = vnet_get_tcp_main ();
+  TCP_EVT_DBG (TCP_EVT_UNBIND,
+	       pool_elt_at_index (tm->listener_pool, listener_index));
   pool_put_index (tm->listener_pool, listener_index);
 }
 
 u32
-tcp_session_unbind_ip4 (vlib_main_t * vm, u32 listener_index)
-{
-  tcp_session_unbind (listener_index);
-  return 0;
-}
-
-u32
-tcp_session_unbind_ip6 (vlib_main_t * vm, u32 listener_index)
+tcp_session_unbind (u32 listener_index)
 {
-  tcp_session_unbind (listener_index);
+  tcp_connection_unbind (listener_index);
   return 0;
 }
 
@@ -135,6 +134,7 @@ tcp_connection_cleanup (tcp_connection_t * tc)
 void
 tcp_connection_del (tcp_connection_t * tc)
 {
+  TCP_EVT_DBG (TCP_EVT_DELETE, tc);
   stream_session_delete_notify (&tc->connection);
   tcp_connection_cleanup (tc);
 }
@@ -169,6 +169,8 @@ tcp_connection_reset (tcp_connection_t * tc)
 void
 tcp_connection_close (tcp_connection_t * tc)
 {
+  TCP_EVT_DBG (TCP_EVT_CLOSE, tc);
+
   /* Send FIN if needed */
   if (tc->state == TCP_STATE_ESTABLISHED || tc->state == TCP_STATE_SYN_RCVD
       || tc->state == TCP_STATE_CLOSE_WAIT)
@@ -403,6 +405,8 @@ tcp_connection_open (ip46_address_t * rmt_addr, u16 rmt_port, u8 is_ip4)
 
   tc->state = TCP_STATE_SYN_SENT;
 
+  TCP_EVT_DBG (TCP_EVT_OPEN, tc);
+
   return tc->c_c_index;
 }
 
@@ -418,82 +422,119 @@ tcp_session_open_ip6 (ip46_address_t * addr, u16 port)
   return tcp_connection_open (addr, port, 0);
 }
 
+const char *tcp_dbg_evt_str[] = {
+#define _(sym, str) str,
+  foreach_tcp_dbg_evt
+#undef _
+};
+
+const char *tcp_fsm_states[] = {
+#define _(sym, str) str,
+  foreach_tcp_fsm_state
+#undef _
+};
+
 u8 *
-format_tcp_session_ip4 (u8 * s, va_list * args)
+format_tcp_state (u8 * s, va_list * args)
 {
-  u32 tci = va_arg (*args, u32);
-  u32 thread_index = va_arg (*args, u32);
-  tcp_connection_t *tc;
+  tcp_state_t *state = va_arg (*args, tcp_state_t *);
 
-  tc = tcp_connection_get (tci, thread_index);
+  if (*state < TCP_N_STATES)
+    s = format (s, "%s", tcp_fsm_states[*state]);
+  else
+    s = format (s, "UNKNOWN");
+
+  return s;
+}
+
+const char *tcp_conn_timers[] = {
+#define _(sym, str) str,
+  foreach_tcp_timer
+#undef _
+};
+
+u8 *
+format_tcp_timers (u8 * s, va_list * args)
+{
+  tcp_connection_t *tc = va_arg (*args, tcp_connection_t *);
+  int i, last = 0;
 
-  s = format (s, "[%s] %U:%d->%U:%d", "tcp", format_ip4_address,
-	      &tc->c_lcl_ip4, clib_net_to_host_u16 (tc->c_lcl_port),
-	      format_ip4_address, &tc->c_rmt_ip4,
-	      clib_net_to_host_u16 (tc->c_rmt_port));
+  for (i = 0; i < TCP_N_TIMERS; i++)
+    if (tc->timers[i] != TCP_TIMER_HANDLE_INVALID)
+      last = i;
+
+  s = format (s, "[");
+  for (i = 0; i < last; i++)
+    {
+      if (tc->timers[i] != TCP_TIMER_HANDLE_INVALID)
+	s = format (s, "%s,", tcp_conn_timers[i]);
+    }
+
+  if (last > 0)
+    s = format (s, "%s]", tcp_conn_timers[i]);
+  else
+    s = format (s, "]");
 
   return s;
 }
 
 u8 *
-format_tcp_session_ip6 (u8 * s, va_list * args)
+format_tcp_connection (u8 * s, va_list * args)
 {
-  u32 tci = va_arg (*args, u32);
-  u32 thread_index = va_arg (*args, u32);
-  tcp_connection_t *tc = tcp_connection_get (tci, thread_index);
-  s = format (s, "[%s] %U:%d->%U:%d", "tcp", format_ip6_address,
-	      &tc->c_lcl_ip6, clib_net_to_host_u16 (tc->c_lcl_port),
-	      format_ip6_address, &tc->c_rmt_ip6,
-	      clib_net_to_host_u16 (tc->c_rmt_port));
+  tcp_connection_t *tc = va_arg (*args, tcp_connection_t *);
+
+  if (tc->c_is_ip4)
+    {
+      s = format (s, "[#%d][%s] %U:%d->%U:%d", tc->c_thread_index, "T",
+		  format_ip4_address, &tc->c_lcl_ip4,
+		  clib_net_to_host_u16 (tc->c_lcl_port), format_ip4_address,
+		  &tc->c_rmt_ip4, clib_net_to_host_u16 (tc->c_rmt_port));
+    }
+  else
+    {
+      s = format (s, "[#%d][%s] %U:%d->%U:%d", tc->c_thread_index, "T",
+		  format_ip6_address, &tc->c_lcl_ip6,
+		  clib_net_to_host_u16 (tc->c_lcl_port), format_ip6_address,
+		  &tc->c_rmt_ip6, clib_net_to_host_u16 (tc->c_rmt_port));
+    }
+
   return s;
 }
 
 u8 *
-format_tcp_listener_session_ip4 (u8 * s, va_list * args)
+format_tcp_connection_verbose (u8 * s, va_list * args)
 {
-  u32 tci = va_arg (*args, u32);
-  tcp_connection_t *tc = tcp_listener_get (tci);
-  s = format (s, "[%s] %U:%d->%U:%d", "tcp", format_ip4_address,
-	      &tc->c_lcl_ip4, clib_net_to_host_u16 (tc->c_lcl_port),
-	      format_ip4_address, &tc->c_rmt_ip4,
-	      clib_net_to_host_u16 (tc->c_rmt_port));
+  tcp_connection_t *tc = va_arg (*args, tcp_connection_t *);
+  s = format (s, "%U %U %U", format_tcp_connection, tc, format_tcp_state,
+	      &tc->state, format_tcp_timers, tc);
   return s;
 }
 
 u8 *
-format_tcp_listener_session_ip6 (u8 * s, va_list * args)
+format_tcp_session (u8 * s, va_list * args)
 {
   u32 tci = va_arg (*args, u32);
-  tcp_connection_t *tc = tcp_listener_get (tci);
-  s = format (s, "[%s] %U:%d->%U:%d", "tcp", format_ip6_address,
-	      &tc->c_lcl_ip6, clib_net_to_host_u16 (tc->c_lcl_port),
-	      format_ip6_address, &tc->c_rmt_ip6,
-	      clib_net_to_host_u16 (tc->c_rmt_port));
-  return s;
+  u32 thread_index = va_arg (*args, u32);
+  tcp_connection_t *tc;
+
+  tc = tcp_connection_get (tci, thread_index);
+  return format (s, "%U", format_tcp_connection, tc);
 }
 
 u8 *
-format_tcp_half_open_session_ip4 (u8 * s, va_list * args)
+format_tcp_listener_session (u8 * s, va_list * args)
 {
   u32 tci = va_arg (*args, u32);
-  tcp_connection_t *tc = tcp_half_open_connection_get (tci);
-  s = format (s, "[%s] %U:%d->%U:%d", "tcp", format_ip4_address,
-	      &tc->c_lcl_ip4, clib_net_to_host_u16 (tc->c_lcl_port),
-	      format_ip4_address, &tc->c_rmt_ip4,
-	      clib_net_to_host_u16 (tc->c_rmt_port));
-  return s;
+  tcp_connection_t *tc = tcp_listener_get (tci);
+  return format (s, "%U", format_tcp_connection, tc);
 }
 
 u8 *
-format_tcp_half_open_session_ip6 (u8 * s, va_list * args)
+format_tcp_half_open_session (u8 * s, va_list * args)
 {
   u32 tci = va_arg (*args, u32);
   tcp_connection_t *tc = tcp_half_open_connection_get (tci);
-  s = format (s, "[%s] %U:%d->%U:%d", "tcp", format_ip6_address,
-	      &tc->c_lcl_ip6, clib_net_to_host_u16 (tc->c_lcl_port),
-	      format_ip6_address, &tc->c_rmt_ip6,
-	      clib_net_to_host_u16 (tc->c_rmt_port));
-  return s;
+  return format (s, "%U", format_tcp_connection, tc);
 }
 
 transport_connection_t *
@@ -534,7 +575,7 @@ tcp_session_tx_fifo_offset (transport_connection_t * trans_conn)
 /* *INDENT-OFF* */
 const static transport_proto_vft_t tcp4_proto = {
   .bind = tcp_session_bind_ip4,
-  .unbind = tcp_session_unbind_ip4,
+  .unbind = tcp_session_unbind,
   .push_header = tcp_push_header,
   .get_connection = tcp_session_get_transport,
   .get_listener = tcp_session_get_listener,
@@ -545,14 +586,14 @@ const static transport_proto_vft_t tcp4_proto = {
   .send_mss = tcp_session_send_mss,
   .send_space = tcp_session_send_space,
   .tx_fifo_offset = tcp_session_tx_fifo_offset,
-  .format_connection = format_tcp_session_ip4,
-  .format_listener = format_tcp_listener_session_ip4,
-  .format_half_open = format_tcp_half_open_session_ip4
+  .format_connection = format_tcp_session,
+  .format_listener = format_tcp_listener_session,
+  .format_half_open = format_tcp_half_open_session,
 };
 
 const static transport_proto_vft_t tcp6_proto = {
   .bind = tcp_session_bind_ip6,
-  .unbind = tcp_session_unbind_ip6,
+  .unbind = tcp_session_unbind,
   .push_header = tcp_push_header,
   .get_connection = tcp_session_get_transport,
   .get_listener = tcp_session_get_listener,
@@ -563,9 +604,9 @@ const static transport_proto_vft_t tcp6_proto = {
   .send_mss = tcp_session_send_mss,
   .send_space = tcp_session_send_space,
   .tx_fifo_offset = tcp_session_tx_fifo_offset,
-  .format_connection = format_tcp_session_ip6,
-  .format_listener = format_tcp_listener_session_ip6,
-  .format_half_open = format_tcp_half_open_session_ip6
+  .format_connection = format_tcp_session,
+  .format_listener = format_tcp_listener_session,
+  .format_half_open = format_tcp_half_open_session,
 };
 /* *INDENT-ON* */
 
@@ -654,6 +695,8 @@ tcp_expired_timers_dispatch (u32 * expired_timers)
       connection_index = expired_timers[i] & 0x0FFFFFFF;
       timer_id = expired_timers[i] >> 28;
 
+      TCP_EVT_DBG (TCP_EVT_TIMER_POP, connection_index, timer_id);
+
       /* Handle expiration */
       (*timer_expiration_handlers[timer_id]) (connection_index);
     }
diff --git a/src/vnet/tcp/tcp.h b/src/vnet/tcp/tcp.h
index 3b3d8fc7cff..082ab1d8b1c 100644
--- a/src/vnet/tcp/tcp.h
+++ b/src/vnet/tcp/tcp.h
@@ -22,6 +22,7 @@
 #include <vnet/tcp/tcp_timer.h>
 #include <vnet/session/transport.h>
 #include <vnet/session/session.h>
+#include <vnet/tcp/tcp_debug.h>
 
 #define TCP_TICK 10e-3			/**< TCP tick period (s) */
 #define THZ 1/TCP_TICK			/**< TCP tick frequency */
@@ -222,7 +223,7 @@ typedef struct _tcp_connection
   u32 prev_ssthresh;	/**< ssthresh before congestion */
   u32 bytes_acked;	/**< Bytes acknowledged by current segment */
   u32 rtx_bytes;	/**< Retransmitted bytes */
-  u32 tsecr_last_ack;	/**< Timestamp echoed to us in last health ACK */
+  u32 tsecr_last_ack;	/**< Timestamp echoed to us in last healthy ACK */
   tcp_cc_algorithm_t *cc_algo;	/**< Congestion control algorithm */
 
   /* RTT and RTO */
@@ -354,6 +355,9 @@ void tcp_connection_cleanup (tcp_connection_t * tc);
 void tcp_connection_del (tcp_connection_t * tc);
 void tcp_connection_reset (tcp_connection_t * tc);
 
+u8 *format_tcp_connection (u8 * s, va_list * args);
+u8 *format_tcp_connection_verbose (u8 * s, va_list * args);
+
 always_inline tcp_connection_t *
 tcp_listener_get (u32 tli)
 {
diff --git a/src/vnet/tcp/tcp_debug.h b/src/vnet/tcp/tcp_debug.h
new file mode 100644
index 00000000000..069c512da26
--- /dev/null
+++ b/src/vnet/tcp/tcp_debug.h
@@ -0,0 +1,316 @@
+/*
+ * Copyright (c) 2017 Cisco and/or its affiliates.
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at:
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#ifndef SRC_VNET_TCP_TCP_DEBUG_H_
+#define SRC_VNET_TCP_TCP_DEBUG_H_
+
+#include <vlib/vlib.h>
+
+#define TCP_DEBUG (1)
+
+#define foreach_tcp_dbg_evt		\
+  _(INIT, "")				\
+  _(DEALLOC, "")			\
+  _(OPEN, "open")			\
+  _(CLOSE, "close")			\
+  _(BIND, "bind")			\
+  _(UNBIND, "unbind")			\
+  _(DELETE, "delete")			\
+  _(SYN_SENT, "SYN sent")		\
+  _(FIN_SENT, "FIN sent")		\
+  _(RST_SENT, "RST sent")		\
+  _(SYN_RCVD, "SYN rcvd")		\
+  _(ACK_RCVD, "ACK rcvd")		\
+  _(FIN_RCVD, "FIN rcvd")		\
+  _(RST_RCVD, "RST rcvd")		\
+  _(PKTIZE, "packetize")		\
+  _(INPUT, "in")			\
+  _(TIMER_POP, "timer pop")
+
+typedef enum _tcp_dbg
+{
+#define _(sym, str) TCP_DBG_##sym,
+  foreach_tcp_dbg_evt
+#undef _
+} tcp_dbg_e;
+
+typedef enum _tcp_dbg_evt
+{
+#define _(sym, str) TCP_EVT_##sym,
+  foreach_tcp_dbg_evt
+#undef _
+} tcp_dbg_evt_e;
+
+#if TCP_DEBUG
+
+#define TRANSPORT_DEBUG (1)
+
+#define TCP_DBG(_tc, _evt, _args...)					\
+{   		            						\
+    u8 *_tmp = 0;							\
+    _tmp = format(_tmp, "%U", format_tcp_connection_verbose, _tc);	\
+    clib_warning("%s", _tmp);						\
+    vec_free(_tmp);							\
+}
+
+#define DECLARE_ETD(_tc, _e, _size)					\
+  struct								\
+  {									\
+    u32 data[_size];							\
+  } * ed;								\
+  ed = ELOG_TRACK_DATA (&vlib_global_main.elog_main,			\
+			_e, _tc->c_elog_track)
+
+#define TCP_EVT_INIT_HANDLER(_tc, ...)					\
+{									\
+  _tc->c_elog_track.name = 						\
+	(char *) format (0, "%d%c", _tc->c_c_index, 0);			\
+  elog_track_register (&vlib_global_main.elog_main, &_tc->c_elog_track);\
+}
+
+#define TCP_EVT_DEALLOC_HANDLER(_tc, ...)				\
+{									\
+  vec_free (_tc->c_elog_track.name);					\
+}
+
+#define TCP_EVT_OPEN_HANDLER(_tc, ...)					\
+{									\
+  TCP_EVT_INIT_HANDLER(_tc);						\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "open: index %d",						\
+    .format_args = "i4",						\
+  };									\
+  DECLARE_ETD(_tc, _e, 1);						\
+  ed->data[0] = _tc->c_c_index;						\
+}
+
+#define TCP_EVT_CLOSE_HANDLER(_tc, ...)					\
+{									\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "close: %d",						\
+    .format_args = "i4",						\
+  };									\
+  DECLARE_ETD(_tc, _e, 1);						\
+  ed->data[0] = _tc->c_c_index;						\
+}
+
+#define TCP_EVT_BIND_HANDLER(_tc, ...)					\
+{									\
+  TCP_EVT_INIT_HANDLER(_tc);						\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "bind: listener %d",					\
+  };									\
+  DECLARE_ETD(_tc, _e, 1);						\
+  ed->data[0] = _tc->c_c_index;						\
+}
+
+#define TCP_EVT_UNBIND_HANDLER(_tc, ...)				\
+{									\
+  TCP_EVT_DEALLOC_HANDLER(_tc);						\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "unbind: listener %d",					\
+  };									\
+  DECLARE_ETD(_tc, _e, 1);						\
+  ed->data[0] = _tc->c_c_index;						\
+  TCP_EVT_DEALLOC_HANDLER(_tc);						\
+}
+
+#define TCP_EVT_DELETE_HANDLER(_tc, ...)				\
+{									\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "delete: %d",						\
+    .format_args = "i4",						\
+  };									\
+  DECLARE_ETD(_tc, _e, 0);						\
+  ed->data[0] = _tc->c_c_index;						\
+  TCP_EVT_DEALLOC_HANDLER(_tc);						\
+}
+
+#define TCP_EVT_SYN_SENT_HANDLER(_tc, ...)				\
+{									\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "SYN: iss %d",						\
+    .format_args = "i4",						\
+  };									\
+  DECLARE_ETD(_tc, _e, 1);						\
+  ed->data[0] = _tc->iss;						\
+}
+
+#define TCP_EVT_FIN_SENT_HANDLER(_tc, ...)				\
+{									\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "FIN: 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;				\
+}
+
+#define TCP_EVT_RST_SENT_HANDLER(_tc, ...)				\
+{									\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "RST: 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;				\
+}
+
+#define TCP_EVT_SYN_RCVD_HANDLER(_tc, ...)				\
+{									\
+  TCP_EVT_INIT_HANDLER(_tc);						\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "SYN rcvd: irs %d",					\
+    .format_args = "i4",						\
+  };									\
+  DECLARE_ETD(_tc, _e, 1);						\
+  ed->data[0] = _tc->irs;						\
+}
+
+#define TCP_EVT_FIN_RCVD_HANDLER(_tc, ...)				\
+{									\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "FIN rcvd: 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;				\
+}
+
+#define TCP_EVT_RST_RCVD_HANDLER(_tc, ...)				\
+{									\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "RST rcvd: 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;				\
+}
+
+#define TCP_EVT_ACK_RCVD_HANDLER(_tc, ...)				\
+{									\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "ACK: acked %u cwnd %u inflight %u",			\
+    .format_args = "i4i4i4",						\
+  };									\
+  DECLARE_ETD(_tc, _e, 3);						\
+  ed->data[0] = _tc->bytes_acked;					\
+  ed->data[1] = _tc->cwnd;						\
+  ed->data[2] = tcp_flight_size(_tc);					\
+}
+
+#define TCP_EVT_PKTIZE_HANDLER(_tc, ...)				\
+{									\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "pktize: snd_una %u snd_nxt %u una_max %u",		\
+    .format_args = "i4i4i4",						\
+  };									\
+  DECLARE_ETD(_tc, _e, 3);						\
+  ed->data[0] = _tc->snd_una - _tc->iss;				\
+  ed->data[1] = _tc->snd_nxt - _tc->iss;				\
+  ed->data[2] = _tc->snd_una_max - _tc->iss;				\
+}
+
+#define TCP_EVT_OUTPUT_HANDLER(_tc, flags, n_bytes,...)			\
+{									\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "out: flags %x, bytes %u",				\
+    .format_args = "i4i4",						\
+  };									\
+  DECLARE_ETD(_tc, _e, 2);						\
+  ed->data[0] = flags;							\
+  ed->data[1] = n_bytes;						\
+}
+
+#define TCP_EVT_INPUT_HANDLER(_tc, n_bytes, ...)			\
+{									\
+  ELOG_TYPE_DECLARE (_e) =						\
+  {									\
+    .format = "in: bytes %u rcv_nxt %u",				\
+    .format_args = "i4i4",						\
+  };									\
+  DECLARE_ETD(_tc, _e, 2);						\
+  ed->data[0] = n_bytes;						\
+  ed->data[1] = _tc->rcv_nxt - _tc->irs;				\
+}
+
+#define TCP_EVT_TIMER_POP_HANDLER(_tc_index, _timer_id, ...)            \
+{                                                               	\
+  tcp_connection_t *_tc;                                        	\
+  if (_timer_id == TCP_TIMER_RETRANSMIT_SYN)                           	\
+    {                                                           	\
+      _tc = tcp_half_open_connection_get (_tc_index);           	\
+    }                                                           	\
+  else                                                          	\
+    {                                                           	\
+      u32 _thread_index = os_get_cpu_number ();                 	\
+      _tc = tcp_connection_get (_tc_index, _thread_index);      	\
+    }                                                           	\
+  ELOG_TYPE_DECLARE (_e) =                                      	\
+  {                                                             	\
+    .format = "TimerPop: %s (%d)",                              	\
+    .format_args = "t4i4",                                      	\
+    .n_enum_strings = 7,                                        	\
+    .enum_strings = {                                           	\
+      "retransmit",                                             	\
+      "delack",                                                 	\
+      "BUG",                                                    	\
+      "keep",                                                   	\
+      "waitclose",                                              	\
+      "retransmit syn",                                         	\
+      "establish",                                              	\
+    },                                                          	\
+  };                                                            	\
+  DECLARE_ETD(_tc, _e, 2);                                      	\
+  ed->data[0] = _timer_id;                                      	\
+  ed->data[1] = _timer_id;                                      	\
+}
+
+#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)
+
+#else
+#define TCP_EVT_DBG(_evt, _args...)
+#endif
+
+
+#endif /* SRC_VNET_TCP_TCP_DEBUG_H_ */
+/*
+ * fd.io coding-style-patch-verification: ON
+ *
+ * Local Variables:
+ * eval: (c-set-style "gnu")
+ * End:
+ */
diff --git a/src/vnet/tcp/tcp_input.c b/src/vnet/tcp/tcp_input.c
index f19fbf874dc..67af4321bd3 100644
--- a/src/vnet/tcp/tcp_input.c
+++ b/src/vnet/tcp/tcp_input.c
@@ -730,6 +730,8 @@ tcp_rcv_ack (tcp_connection_t * tc, vlib_buffer_t * b,
   /* Updates congestion control (slow start/congestion avoidance) */
   tcp_cc_rcv_ack (tc);
 
+  TCP_EVT_DBG (TCP_EVT_ACK_RCVD, tc);
+
   /* If everything has been acked, stop retransmit timer
    * otherwise update */
   if (tc->snd_una == tc->snd_una_max)
@@ -922,6 +924,8 @@ tcp_segment_rcv (tcp_main_t * tm, tcp_connection_t * tc, vlib_buffer_t * b,
    * segments can be enqueued after fifo tail offset changes. */
   error = tcp_session_enqueue_data (tc, b, n_data_bytes);
 
+  TCP_EVT_DBG (TCP_EVT_INPUT, tc, n_data_bytes);
+
   /* Check if ACK can be delayed */
   if (tcp_can_delack (tc))
     {
@@ -1079,6 +1083,7 @@ tcp46_established_inline (vlib_main_t * vm, vlib_node_runtime_t * node,
 	       * wait for session to call close. To avoid lingering
 	       * in CLOSE-WAIT, set timer (reuse WAITCLOSE). */
 	      tc0->state = TCP_STATE_CLOSE_WAIT;
+	      TCP_EVT_DBG (TCP_EVT_FIN_RCVD, tc0);
 	      stream_session_disconnect_notify (&tc0->connection);
 	      tcp_timer_set (tc0, TCP_TIMER_WAITCLOSE, TCP_CLOSEWAIT_TIME);
 	    }
@@ -1134,7 +1139,8 @@ VLIB_REGISTER_NODE (tcp4_established_node) =
   .name = "tcp4-established",
   /* Takes a vector of packets. */
   .vector_size = sizeof (u32),
-  .n_errors = TCP_N_ERROR,.error_strings = tcp_error_strings,
+  .n_errors = TCP_N_ERROR,
+  .error_strings = tcp_error_strings,
   .n_next_nodes = TCP_ESTABLISHED_N_NEXT,
   .next_nodes =
   {
@@ -1363,7 +1369,7 @@ tcp46_syn_sent_inline (vlib_main_t * vm, vlib_node_runtime_t * node,
 	    {
 	      new_tc0->state = TCP_STATE_SYN_RCVD;
 
-	      /* Notify app that we have connection XXX */
+	      /* Notify app that we have connection */
 	      stream_session_connect_notify (&new_tc0->connection, sst, 0);
 
 	      tcp_make_synack (new_tc0, b0);
@@ -1726,7 +1732,7 @@ tcp46_rcv_process_inline (vlib_main_t * vm, vlib_node_runtime_t * node,
 	    case TCP_STATE_FIN_WAIT_2:
 	      /* Got FIN, send ACK! */
 	      tc0->state = TCP_STATE_TIME_WAIT;
-	      tcp_timer_set (tc0, TCP_TIMER_WAITCLOSE, TCP_2MSL_TIME);
+	      tcp_timer_set (tc0, TCP_TIMER_WAITCLOSE, TCP_CLOSEWAIT_TIME);
 	      tcp_make_ack (tc0, b0);
 	      next0 = tcp_next_output (is_ip4);
 	      break;
@@ -1737,6 +1743,7 @@ tcp46_rcv_process_inline (vlib_main_t * vm, vlib_node_runtime_t * node,
 	      tcp_timer_update (tc0, TCP_TIMER_WAITCLOSE, TCP_2MSL_TIME);
 	      break;
 	    }
+	  TCP_EVT_DBG (TCP_EVT_FIN_RCVD, tc0);
 
 	  b0->error = error0 ? node->errors[error0] : 0;
 
@@ -1950,6 +1957,8 @@ tcp46_listen_inline (vlib_main_t * vm, vlib_node_runtime_t * node,
 
 	  tcp_connection_init_vars (child0);
 
+	  TCP_EVT_DBG (TCP_EVT_SYN_RCVD, child0);
+
 	  /* Reuse buffer to make syn-ack and send */
 	  tcp_make_synack (child0, b0);
 	  next0 = tcp_next_output (is_ip4);
@@ -2064,25 +2073,6 @@ typedef struct
   u8 state;
 } tcp_rx_trace_t;
 
-const char *tcp_fsm_states[] = {
-#define _(sym, str) str,
-  foreach_tcp_fsm_state
-#undef _
-};
-
-u8 *
-format_tcp_state (u8 * s, va_list * args)
-{
-  tcp_state_t *state = va_arg (*args, tcp_state_t *);
-
-  if (state[0] < TCP_N_STATES)
-    s = format (s, "%s", tcp_fsm_states[state[0]]);
-  else
-    s = format (s, "UNKNOWN");
-
-  return s;
-}
-
 u8 *
 format_tcp_rx_trace (u8 * s, va_list * args)
 {
diff --git a/src/vnet/tcp/tcp_output.c b/src/vnet/tcp/tcp_output.c
index aa43e9f37f0..114a5b9e0f1 100644
--- a/src/vnet/tcp/tcp_output.c
+++ b/src/vnet/tcp/tcp_output.c
@@ -452,11 +452,7 @@ tcp_make_fin (tcp_connection_t * tc, vlib_buffer_t * b)
 
   tcp_reuse_buffer (vm, b);
 
-  if (tc->rcv_las == tc->rcv_nxt)
-    flags = TCP_FLAG_FIN;
-  else
-    flags = TCP_FLAG_FIN | TCP_FLAG_ACK;
-
+  flags = TCP_FLAG_FIN | TCP_FLAG_ACK;
   tcp_make_ack_i (tc, b, TCP_STATE_ESTABLISHED, flags);
 
   /* Reset flags, make sure ack is sent */
@@ -828,6 +824,7 @@ tcp_send_fin (tcp_connection_t * tc)
   tcp_make_fin (tc, b);
   tcp_enqueue_to_output (vm, b, bi, tc->c_is_ip4);
   tc->flags |= TCP_CONN_FINSNT;
+  TCP_EVT_DBG (TCP_EVT_FIN_SENT, tc);
 }
 
 always_inline u8
@@ -887,6 +884,7 @@ tcp_push_hdr_i (tcp_connection_t * tc, vlib_buffer_t * b,
   vnet_buffer (b)->tcp.connection_index = tc->c_c_index;
 
   tc->snd_nxt += data_len;
+  TCP_EVT_DBG (TCP_EVT_PKTIZE, tc);
 }
 
 /* Send delayed ACK when timer expires */
@@ -1186,6 +1184,7 @@ tcp46_output_inline (vlib_main_t * vm,
 	    }
 
 	  th0 = vlib_buffer_get_current (b0);
+	  TCP_EVT_DBG (TCP_EVT_OUTPUT, tc0, th0->flags, b0->current_length);
 
 	  if (is_ip4)
 	    {
@@ -1242,22 +1241,6 @@ tcp46_output_inline (vlib_main_t * vm,
 		  tc0->rtt_ts = tcp_time_now ();
 		  tc0->rtt_seq = tc0->snd_nxt;
 		}
-
-	      if (1)
-		{
-		  ELOG_TYPE_DECLARE (e) =
-		  {
-		  .format =
-		      "output: snd_una %u snd_una_max %u",.format_args =
-		      "i4i4",};
-		  struct
-		  {
-		    u32 data[2];
-		  } *ed;
-		  ed = ELOG_DATA (&vm->elog_main, e);
-		  ed->data[0] = tc0->snd_una - tc0->iss;
-		  ed->data[1] = tc0->snd_una_max - tc0->iss;
-		}
 	    }
 
 	  /* Set the retransmit timer if not set already and not
@@ -1275,9 +1258,8 @@ tcp46_output_inline (vlib_main_t * vm,
 	  vnet_buffer (b0)->sw_if_index[VLIB_TX] = (u32) ~ 0;
 
 	  b0->flags |= VNET_BUFFER_LOCALLY_ORIGINATED;
-
 	done:
-	  b0->error = error0 != 0 ? node->errors[error0] : 0;
+	  b0->error = node->errors[error0];
 	  if (PREDICT_FALSE (b0->flags & VLIB_BUFFER_IS_TRACED))
 	    {
 
@@ -1307,34 +1289,50 @@ tcp6_output (vlib_main_t * vm, vlib_node_runtime_t * node,
   return tcp46_output_inline (vm, node, from_frame, 0 /* is_ip4 */ );
 }
 
+/* *INDENT-OFF* */
 VLIB_REGISTER_NODE (tcp4_output_node) =
 {
   .function = tcp4_output,.name = "tcp4-output",
     /* Takes a vector of packets. */
-    .vector_size = sizeof (u32),.n_errors = TCP_N_ERROR,.error_strings =
-    tcp_error_strings,.n_next_nodes = TCP_OUTPUT_N_NEXT,.next_nodes =
-  {
+    .vector_size = sizeof (u32),
+    .n_errors = TCP_N_ERROR,
+    .error_strings = tcp_error_strings,
+    .n_next_nodes = TCP_OUTPUT_N_NEXT,
+    .next_nodes = {
 #define _(s,n) [TCP_OUTPUT_NEXT_##s] = n,
     foreach_tcp4_output_next
 #undef _
-  }
-,.format_buffer = format_tcp_header,.format_trace = format_tcp_tx_trace,};
+    },
+    .format_buffer = format_tcp_header,
+    .format_trace = format_tcp_tx_trace,
+};
+/* *INDENT-ON* */
 
-VLIB_NODE_FUNCTION_MULTIARCH (tcp4_output_node, tcp4_output)
+VLIB_NODE_FUNCTION_MULTIARCH (tcp4_output_node, tcp4_output);
+
+/* *INDENT-OFF* */
 VLIB_REGISTER_NODE (tcp6_output_node) =
 {
-  .function = tcp6_output,.name = "tcp6-output",
+  .function = tcp6_output,
+  .name = "tcp6-output",
     /* Takes a vector of packets. */
-    .vector_size = sizeof (u32),.n_errors = TCP_N_ERROR,.error_strings =
-    tcp_error_strings,.n_next_nodes = TCP_OUTPUT_N_NEXT,.next_nodes =
-  {
+  .vector_size = sizeof (u32),
+  .n_errors = TCP_N_ERROR,
+  .error_strings = tcp_error_strings,
+  .n_next_nodes = TCP_OUTPUT_N_NEXT,
+  .next_nodes = {
 #define _(s,n) [TCP_OUTPUT_NEXT_##s] = n,
     foreach_tcp6_output_next
 #undef _
-  }
-,.format_buffer = format_tcp_header,.format_trace = format_tcp_tx_trace,};
+  },
+  .format_buffer = format_tcp_header,
+  .format_trace = format_tcp_tx_trace,
+};
+/* *INDENT-ON* */
+
+VLIB_NODE_FUNCTION_MULTIARCH (tcp6_output_node, tcp6_output);
 
-VLIB_NODE_FUNCTION_MULTIARCH (tcp6_output_node, tcp6_output) u32
+u32
 tcp_push_header (transport_connection_t * tconn, vlib_buffer_t * b)
 {
   tcp_connection_t *tc;
@@ -1405,7 +1403,7 @@ tcp46_send_reset_inline (vlib_main_t * vm, vlib_node_runtime_t * node,
 	  next0 = TCP_RESET_NEXT_IP_LOOKUP;
 
 	done:
-	  b0->error = error0 != 0 ? node->errors[error0] : 0;
+	  b0->error = node->errors[error0];
 	  b0->flags |= VNET_BUFFER_LOCALLY_ORIGINATED;
 	  if (PREDICT_FALSE (b0->flags & VLIB_BUFFER_IS_TRACED))
 	    {
@@ -1450,6 +1448,8 @@ VLIB_REGISTER_NODE (tcp4_reset_node) = {
 };
 /* *INDENT-ON* */
 
+VLIB_NODE_FUNCTION_MULTIARCH (tcp4_reset_node, tcp4_send_reset);
+
 /* *INDENT-OFF* */
 VLIB_REGISTER_NODE (tcp6_reset_node) = {
   .function = tcp6_send_reset,
@@ -1466,6 +1466,8 @@ VLIB_REGISTER_NODE (tcp6_reset_node) = {
 };
 /* *INDENT-ON* */
 
+VLIB_NODE_FUNCTION_MULTIARCH (tcp6_reset_node, tcp6_send_reset);
+
 /*
  * fd.io coding-style-patch-verification: ON
  *