session: add session event log for session state

To aid sesipon debug, add session event log in SM debug to track
the session state.

Type: improvement

Signed-off-by: Steven Luong <sluong@cisco.com>
Change-Id: I6909cf969cd5b6a3ea5a06d08ae32c2f1d48f686

5 files changed, 68 insertions, 35 deletions

diff --git a/src/vnet/session/application_local.c b/src/vnet/session/application_local.c
index 8590d041600..d2a69dc282b 100644
--- a/src/vnet/session/application_local.c
+++ b/src/vnet/session/application_local.c
@@ -363,7 +363,7 @@ ct_session_connect_notify (session_t *ss, session_error_t err)
   ss = session_get (ss_index, thread_index);
   cs->session_type = ss->session_type;
   cs->listener_handle = SESSION_INVALID_HANDLE;
-  cs->session_state = SESSION_STATE_CONNECTING;
+  session_set_state (cs, SESSION_STATE_CONNECTING);
   cs->app_wrk_index = client_wrk->wrk_index;
   cs->connection_index = cct->c_c_index;
   cct->c_s_index = cs->session_index;
@@ -379,7 +379,7 @@ ct_session_connect_notify (session_t *ss, session_error_t err)
       goto connect_error;
     }
 
-  cs->session_state = SESSION_STATE_CONNECTING;
+  session_set_state (cs, SESSION_STATE_CONNECTING);
 
   if (app_worker_connect_notify (client_wrk, cs, 0, opaque))
     {
@@ -390,7 +390,7 @@ ct_session_connect_notify (session_t *ss, session_error_t err)
     }
 
   cs = session_get (cct->c_s_index, cct->c_thread_index);
-  cs->session_state = SESSION_STATE_READY;
+  session_set_state (cs, SESSION_STATE_READY);
 
   return 0;
 
@@ -701,7 +701,7 @@ ct_accept_one (u32 thread_index, u32 ho_index)
 						     sct->c_is_ip4);
   ss->connection_index = sct->c_c_index;
   ss->listener_handle = listen_session_get_handle (ll);
-  ss->session_state = SESSION_STATE_CREATED;
+  session_set_state (ss, SESSION_STATE_CREATED);
 
   server_wrk = application_listener_select_worker (ll);
   ss->app_wrk_index = server_wrk->wrk_index;
@@ -726,7 +726,7 @@ ct_accept_one (u32 thread_index, u32 ho_index)
   cct->client_tx_fifo->refcnt++;
   cct->segment_handle = sct->segment_handle;
 
-  ss->session_state = SESSION_STATE_ACCEPTING;
+  session_set_state (ss, SESSION_STATE_ACCEPTING);
   if (app_worker_accept_notify (server_wrk, ss))
     {
       ct_session_connect_notify (ss, SESSION_E_REFUSED);
diff --git a/src/vnet/session/session.c b/src/vnet/session/session.c
index 4c57b1ac9bb..a56ff9fe800 100644
--- a/src/vnet/session/session.c
+++ b/src/vnet/session/session.c
@@ -299,7 +299,7 @@ session_cleanup_half_open (session_handle_t ho_handle)
        * session should be removed. */
       if (ho->connection_index == ~0)
 	{
-	  ho->session_state = SESSION_STATE_CLOSED;
+	  session_set_state (ho, SESSION_STATE_CLOSED);
 	  return;
 	}
       /* Migrated transports are no longer half-opens */
@@ -386,7 +386,7 @@ session_alloc_for_connection (transport_connection_t * tc)
 
   s = session_alloc (thread_index);
   s->session_type = session_type_from_proto_and_ip (tc->proto, tc->is_ip4);
-  s->session_state = SESSION_STATE_CLOSED;
+  session_set_state (s, SESSION_STATE_CLOSED);
 
   /* Attach transport to session and vice versa */
   s->connection_index = tc->c_index;
@@ -894,7 +894,7 @@ session_stream_connect_notify (transport_connection_t * tc,
     return app_worker_connect_notify (app_wrk, s, err, opaque);
 
   s = session_alloc_for_connection (tc);
-  s->session_state = SESSION_STATE_CONNECTING;
+  session_set_state (s, SESSION_STATE_CONNECTING);
   s->app_wrk_index = app_wrk->wrk_index;
   new_si = s->session_index;
   new_ti = s->thread_index;
@@ -907,7 +907,7 @@ session_stream_connect_notify (transport_connection_t * tc,
     }
 
   s = session_get (new_si, new_ti);
-  s->session_state = SESSION_STATE_READY;
+  session_set_state (s, SESSION_STATE_READY);
   session_lookup_add_connection (tc, session_handle (s));
 
   if (app_worker_connect_notify (app_wrk, s, SESSION_E_NONE, opaque))
@@ -1037,7 +1037,7 @@ session_dgram_connect_notify (transport_connection_t * tc,
    */
   new_s = session_clone_safe (tc->s_index, old_thread_index);
   new_s->connection_index = tc->c_index;
-  new_s->session_state = SESSION_STATE_READY;
+  session_set_state (new_s, SESSION_STATE_READY);
   new_s->flags |= SESSION_F_IS_MIGRATING;
 
   if (!(tc->flags & TRANSPORT_CONNECTION_F_NO_LOOKUP))
@@ -1091,11 +1091,11 @@ session_transport_closing_notify (transport_connection_t * tc)
    * accept might be rejected */
   if (s->session_state == SESSION_STATE_ACCEPTING)
     {
-      s->session_state = SESSION_STATE_TRANSPORT_CLOSING;
+      session_set_state (s, SESSION_STATE_TRANSPORT_CLOSING);
       return;
     }
 
-  s->session_state = SESSION_STATE_TRANSPORT_CLOSING;
+  session_set_state (s, SESSION_STATE_TRANSPORT_CLOSING);
   app_wrk = app_worker_get (s->app_wrk_index);
   app_worker_close_notify (app_wrk, s);
 }
@@ -1136,7 +1136,7 @@ session_transport_delete_notify (transport_connection_t * tc)
        * because transport will soon be closed and closed sessions
        * are assumed to have been removed from the lookup table */
       session_lookup_del_session (s);
-      s->session_state = SESSION_STATE_TRANSPORT_DELETED;
+      session_set_state (s, SESSION_STATE_TRANSPORT_DELETED);
       session_cleanup_notify (s, SESSION_CLEANUP_TRANSPORT);
       svm_fifo_dequeue_drop_all (s->tx_fifo);
       break;
@@ -1147,7 +1147,7 @@ session_transport_delete_notify (transport_connection_t * tc)
        * session is just removed because both transport and app have
        * confirmed the close*/
       session_lookup_del_session (s);
-      s->session_state = SESSION_STATE_TRANSPORT_DELETED;
+      session_set_state (s, SESSION_STATE_TRANSPORT_DELETED);
       session_cleanup_notify (s, SESSION_CLEANUP_TRANSPORT);
       svm_fifo_dequeue_drop_all (s->tx_fifo);
       session_program_transport_ctrl_evt (s, SESSION_CTRL_EVT_CLOSE);
@@ -1191,17 +1191,15 @@ session_transport_closed_notify (transport_connection_t * tc)
     {
       session_transport_closing_notify (tc);
       svm_fifo_dequeue_drop_all (s->tx_fifo);
-      s->session_state = SESSION_STATE_TRANSPORT_CLOSED;
+      session_set_state (s, SESSION_STATE_TRANSPORT_CLOSED);
     }
   /* If app close has not been received or has not yet resulted in
    * a transport close, only mark the session transport as closed */
   else if (s->session_state <= SESSION_STATE_CLOSING)
-    {
-      s->session_state = SESSION_STATE_TRANSPORT_CLOSED;
-    }
+    session_set_state (s, SESSION_STATE_TRANSPORT_CLOSED);
   /* If app also closed, switch to closed */
   else if (s->session_state == SESSION_STATE_APP_CLOSED)
-    s->session_state = SESSION_STATE_CLOSED;
+    session_set_state (s, SESSION_STATE_CLOSED);
 
   app_wrk = app_worker_get_if_valid (s->app_wrk_index);
   if (app_wrk)
@@ -1223,10 +1221,10 @@ session_transport_reset_notify (transport_connection_t * tc)
     return;
   if (s->session_state == SESSION_STATE_ACCEPTING)
     {
-      s->session_state = SESSION_STATE_TRANSPORT_CLOSING;
+      session_set_state (s, SESSION_STATE_TRANSPORT_CLOSING);
       return;
     }
-  s->session_state = SESSION_STATE_TRANSPORT_CLOSING;
+  session_set_state (s, SESSION_STATE_TRANSPORT_CLOSING);
   app_wrk = app_worker_get (s->app_wrk_index);
   app_worker_reset_notify (app_wrk, s);
 }
@@ -1243,12 +1241,12 @@ session_stream_accept_notify (transport_connection_t * tc)
     return -1;
   if (s->session_state != SESSION_STATE_CREATED)
     return 0;
-  s->session_state = SESSION_STATE_ACCEPTING;
+  session_set_state (s, SESSION_STATE_ACCEPTING);
   if (app_worker_accept_notify (app_wrk, s))
     {
       /* On transport delete, no notifications should be sent. Unless, the
        * accept is retried and successful. */
-      s->session_state = SESSION_STATE_CREATED;
+      session_set_state (s, SESSION_STATE_CREATED);
       return -1;
     }
   return 0;
@@ -1266,7 +1264,7 @@ session_stream_accept (transport_connection_t * tc, u32 listener_index,
 
   s = session_alloc_for_connection (tc);
   s->listener_handle = ((u64) thread_index << 32) | (u64) listener_index;
-  s->session_state = SESSION_STATE_CREATED;
+  session_set_state (s, SESSION_STATE_CREATED);
 
   if ((rv = app_worker_init_accepted (s)))
     {
@@ -1310,7 +1308,7 @@ session_dgram_accept (transport_connection_t * tc, u32 listener_index,
     }
 
   session_lookup_add_connection (tc, session_handle (s));
-  s->session_state = SESSION_STATE_ACCEPTING;
+  session_set_state (s, SESSION_STATE_ACCEPTING);
 
   app_wrk = app_worker_get (s->app_wrk_index);
   if ((rv = app_worker_accept_notify (app_wrk, s)))
@@ -1348,7 +1346,7 @@ session_open_cl (session_endpoint_cfg_t *rmt, session_handle_t *rsh)
   app_wrk = app_worker_get (rmt->app_wrk_index);
   s = session_alloc_for_connection (tc);
   s->app_wrk_index = app_wrk->wrk_index;
-  s->session_state = SESSION_STATE_OPENED;
+  session_set_state (s, SESSION_STATE_OPENED);
   if (app_worker_init_connected (app_wrk, s))
     {
       session_free (s);
@@ -1543,7 +1541,7 @@ session_close (session_t * s)
 
   /* App closed so stop propagating dequeue notifications */
   svm_fifo_clear_deq_ntf (s->tx_fifo);
-  s->session_state = SESSION_STATE_CLOSING;
+  session_set_state (s, SESSION_STATE_CLOSING);
   session_program_transport_ctrl_evt (s, SESSION_CTRL_EVT_CLOSE);
 }
 
@@ -1557,7 +1555,7 @@ session_reset (session_t * s)
     return;
   /* Drop all outstanding tx data */
   svm_fifo_dequeue_drop_all (s->tx_fifo);
-  s->session_state = SESSION_STATE_CLOSING;
+  session_set_state (s, SESSION_STATE_CLOSING);
   session_program_transport_ctrl_evt (s, SESSION_CTRL_EVT_RESET);
 }
 
@@ -1592,7 +1590,7 @@ session_transport_close (session_t * s)
   if (s->session_state >= SESSION_STATE_APP_CLOSED)
     {
       if (s->session_state == SESSION_STATE_TRANSPORT_CLOSED)
-	s->session_state = SESSION_STATE_CLOSED;
+	session_set_state (s, SESSION_STATE_CLOSED);
       /* If transport is already deleted, just free the session */
       else if (s->session_state >= SESSION_STATE_TRANSPORT_DELETED)
 	session_free_w_fifos (s);
@@ -1605,7 +1603,7 @@ session_transport_close (session_t * s)
    * delete notify. This will finally lead to the complete cleanup of the
    * session.
    */
-  s->session_state = SESSION_STATE_APP_CLOSED;
+  session_set_state (s, SESSION_STATE_APP_CLOSED);
 
   transport_close (session_get_transport_proto (s), s->connection_index,
 		   s->thread_index);
@@ -1620,13 +1618,13 @@ session_transport_reset (session_t * s)
   if (s->session_state >= SESSION_STATE_APP_CLOSED)
     {
       if (s->session_state == SESSION_STATE_TRANSPORT_CLOSED)
-	s->session_state = SESSION_STATE_CLOSED;
+	session_set_state (s, SESSION_STATE_CLOSED);
       else if (s->session_state >= SESSION_STATE_TRANSPORT_DELETED)
 	session_free_w_fifos (s);
       return;
     }
 
-  s->session_state = SESSION_STATE_APP_CLOSED;
+  session_set_state (s, SESSION_STATE_APP_CLOSED);
   transport_reset (session_get_transport_proto (s), s->connection_index,
 		   s->thread_index);
 }
diff --git a/src/vnet/session/session.h b/src/vnet/session/session.h
index 4fa9194077e..54740e64cf0 100644
--- a/src/vnet/session/session.h
+++ b/src/vnet/session/session.h
@@ -527,6 +527,13 @@ int session_tx_fifo_peek_bytes (transport_connection_t * tc, u8 * buffer,
 				u32 offset, u32 max_bytes);
 u32 session_tx_fifo_dequeue_drop (transport_connection_t * tc, u32 max_bytes);
 
+always_inline void
+session_set_state (session_t *s, session_state_t session_state)
+{
+  s->session_state = session_state;
+  SESSION_EVT (SESSION_EVT_STATE_CHANGE, s);
+}
+
 always_inline u32
 transport_max_rx_enqueue (transport_connection_t * tc)
 {
diff --git a/src/vnet/session/session_debug.h b/src/vnet/session/session_debug.h
index 588d58c790c..614ffc95a7b 100644
--- a/src/vnet/session/session_debug.h
+++ b/src/vnet/session/session_debug.h
@@ -28,6 +28,7 @@
   _ (DISPATCH_START, CLOCKS_EVT_DBG, 1, "dispatch start")                     \
   _ (DISPATCH_END, CLOCKS_EVT_DBG, 1, "dispatch end")                         \
   _ (DSP_CNTRS, CLOCKS_EVT_DBG, 1, "dispatch counters")                       \
+  _ (STATE_CHANGE, SM, 1, "session state change")                             \
   _ (FREE, SM, 1, "session free")                                             \
   _ (IO_EVT_COUNTS, COUNTS_EVT_DBG, 1, "io evt counts")                       \
   _ (COUNTS, COUNTS_EVT_DBG, 1, "ctrl evt counts")
@@ -165,6 +166,32 @@ extern session_dbg_main_t session_dbg_main;
   ed = ELOG_DATA (&vlib_global_main.elog_main, _e)
 
 #if SESSION_SM
+#define SESSION_EVT_STATE_CHANGE_HANDLER(_s)                                  \
+  {                                                                           \
+    ELOG_TYPE_DECLARE (_e) = {						      \
+      .format = "%s: idx %u",                                                 \
+      .format_args = "t4i4",                                                  \
+      .n_enum_strings = 12,					     	      \
+      .enum_strings = {                                           	      \
+		       "created",					      \
+		       "listening",					      \
+		       "connecting",					      \
+		       "accepting",					      \
+		       "ready",						      \
+		       "opened",					      \
+		       "transport closing",				      \
+		       "closing",					      \
+		       "app closed",					      \
+		       "transport closed",				      \
+		       "closed",					      \
+		       "transport deleted",				      \
+		       },						      \
+    };                                   \
+    DEC_SESSION_ETD (_s, _e, 2);                                              \
+    ed->data[0] = _s->session_state;                                          \
+    ed->data[1] = _s->session_index;                                          \
+  }
+
 #define SESSION_EVT_FREE_HANDLER(_s)                                          \
   {                                                                           \
     ELOG_TYPE_DECLARE (_e) = {                                                \
@@ -175,6 +202,7 @@ extern session_dbg_main_t session_dbg_main;
     ed->data[0] = _s->session_index;                                          \
   }
 #else
+#define SESSION_EVT_STATE_CHANGE_HANDLER(_s)
 #define SESSION_EVT_FREE_HANDLER(_s)
 #endif
 
diff --git a/src/vnet/session/session_node.c b/src/vnet/session/session_node.c
index c29e0590aa8..8f6503d2806 100644
--- a/src/vnet/session/session_node.c
+++ b/src/vnet/session/session_node.c
@@ -486,13 +486,13 @@ session_mq_accepted_reply_handler (session_worker_t *wrk,
   /* Special handling for cut-through sessions */
   if (!session_has_transport (s))
     {
-      s->session_state = SESSION_STATE_READY;
+      session_set_state (s, SESSION_STATE_READY);
       ct_session_connect_notify (s, SESSION_E_NONE);
       return;
     }
 
   old_state = s->session_state;
-  s->session_state = SESSION_STATE_READY;
+  session_set_state (s, SESSION_STATE_READY);
 
   if (!svm_fifo_is_empty_prod (s->rx_fifo))
     app_worker_lock_and_send_event (app_wrk, s, SESSION_IO_EVT_RX);
@@ -501,7 +501,7 @@ session_mq_accepted_reply_handler (session_worker_t *wrk,
   if (old_state >= SESSION_STATE_TRANSPORT_CLOSING)
     {
       app_worker_close_notify (app_wrk, s);
-      s->session_state = old_state;
+      session_set_state (s, old_state);
       return;
     }
 }