hsa: fix vpp_echo session close

- Convert asserts in vpp_echo to conditional checks
- Refactor error logging for session creation/deletion
- Fix session close anomalies
- Fix ECHO_* macros
- Add rx/tx results different cmdline options to
  specify pass when counters are different
- Update close tests to send more than the fifo
  sizes of data
- Specify rx/tx results diff options for early
  close tests
- Set listen session state to closed on handling
  unlisten reply

Type: fix

Signed-off-by: Dave Wallace <dwallacelf@gmail.com>
Change-Id: I9d0075fcb18e20829f420da104d69523897b0552

5 files changed, 221 insertions, 78 deletions

diff --git a/src/plugins/hs_apps/sapi/vpp_echo.c b/src/plugins/hs_apps/sapi/vpp_echo.c
index 44e6d1fb36f..085b0fe6083 100644
--- a/src/plugins/hs_apps/sapi/vpp_echo.c
+++ b/src/plugins/hs_apps/sapi/vpp_echo.c
@@ -42,16 +42,28 @@ echo_session_prealloc (echo_main_t * em)
 static void
 echo_assert_test_suceeded (echo_main_t * em)
 {
-  CHECK (ECHO_FAIL_TEST_ASSERT_RX_TOTAL,
-	 em->n_clients * em->bytes_to_receive, em->stats.rx_total,
-	 "Invalid amount of data received");
-  CHECK (ECHO_FAIL_TEST_ASSERT_TX_TOTAL,
-	 em->n_clients * em->bytes_to_send, em->stats.tx_total,
-	 "Invalid amount of data sent");
+  if (em->rx_results_diff)
+    CHECK_DIFF (ECHO_FAIL_TEST_ASSERT_RX_TOTAL,
+		em->n_clients * em->bytes_to_receive, em->stats.rx_total,
+		"Invalid amount of data received");
+  else
+    CHECK_SAME (ECHO_FAIL_TEST_ASSERT_RX_TOTAL,
+		em->n_clients * em->bytes_to_receive, em->stats.rx_total,
+		"Invalid amount of data received");
+
+  if (em->tx_results_diff)
+    CHECK_DIFF (ECHO_FAIL_TEST_ASSERT_TX_TOTAL,
+		em->n_clients * em->bytes_to_send, em->stats.tx_total,
+		"Invalid amount of data sent");
+  else
+    CHECK_SAME (ECHO_FAIL_TEST_ASSERT_TX_TOTAL,
+		em->n_clients * em->bytes_to_send, em->stats.tx_total,
+		"Invalid amount of data sent");
+
   clib_spinlock_lock (&em->sid_vpp_handles_lock);
-  CHECK (ECHO_FAIL_TEST_ASSERT_ALL_SESSIONS_CLOSED,
-	 0, hash_elts (em->session_index_by_vpp_handles),
-	 "Some sessions are still open");
+  CHECK_SAME (ECHO_FAIL_TEST_ASSERT_ALL_SESSIONS_CLOSED,
+	      0, hash_elts (em->session_index_by_vpp_handles),
+	      "Some sessions are still open");
   clib_spinlock_unlock (&em->sid_vpp_handles_lock);
 }
 
@@ -118,7 +130,8 @@ print_global_json_stats (echo_main_t * em)
   u8 *end_evt =
     format (0, "%U", echo_format_timing_event, em->timing.end_event);
   u8 start_evt_missing = !(em->timing.events_sent & em->timing.start_event);
-  u8 end_evt_missing = !(em->timing.events_sent & em->timing.end_event);
+  u8 end_evt_missing = (em->rx_results_diff || em->tx_results_diff) ? 0 :
+    !(em->timing.events_sent & em->timing.end_event);
   f64 deltat = start_evt_missing || end_evt_missing ? 0 :
     em->timing.end_time - em->timing.start_time;
 
@@ -170,7 +183,8 @@ print_global_stats (echo_main_t * em)
   u8 *end_evt =
     format (0, "%U", echo_format_timing_event, em->timing.end_event);
   u8 start_evt_missing = !(em->timing.events_sent & em->timing.start_event);
-  u8 end_evt_missing = !(em->timing.events_sent & em->timing.end_event);
+  u8 end_evt_missing = (em->rx_results_diff || em->tx_results_diff) ? 0 :
+    !(em->timing.events_sent & em->timing.end_event);
   f64 deltat = start_evt_missing || end_evt_missing ? 0 :
     em->timing.end_time - em->timing.start_time;
 
@@ -221,9 +235,9 @@ void
 echo_update_count_on_session_close (echo_main_t * em, echo_session_t * s)
 {
 
-  ECHO_LOG (1, "[%lu/%lu] -> S(%x) -> [%lu/%lu]",
+  ECHO_LOG (1, "[%lu/%lu] -> %U -> [%lu/%lu]",
 	    s->bytes_received, s->bytes_received + s->bytes_to_receive,
-	    s->session_index, s->bytes_sent,
+	    echo_format_session, s, s->bytes_sent,
 	    s->bytes_sent + s->bytes_to_send);
   clib_atomic_fetch_add (&em->stats.tx_total, s->bytes_sent);
   clib_atomic_fetch_add (&em->stats.rx_total, s->bytes_received);
@@ -329,12 +343,23 @@ echo_check_closed_listener (echo_main_t * em, echo_session_t * s)
   echo_session_t *ls;
   /* if parent has died, terminate gracefully */
   if (s->listener_index == SESSION_INVALID_INDEX)
-    return;
+    {
+      ECHO_LOG (2, "%U: listener_index == SESSION_INVALID_INDEX",
+		echo_format_session, s);
+      return;
+    }
   ls = pool_elt_at_index (em->sessions, s->listener_index);
   if (ls->session_state < ECHO_SESSION_STATE_CLOSING)
-    return;
-  ECHO_LOG (2, "Session 0%lx died, close child 0x%lx", ls->vpp_session_handle,
-	    s->vpp_session_handle);
+    {
+      ECHO_LOG (3, "%U: ls->session_state (%d) < "
+		"ECHO_SESSION_STATE_CLOSING (%d)",
+		echo_format_session, ls, ls->session_state,
+		ECHO_SESSION_STATE_CLOSING);
+      return;
+    }
+
+  ECHO_LOG (2, "%U died, close child %U", echo_format_session, ls,
+	    echo_format_session, s);
   echo_update_count_on_session_close (em, s);
   em->proto_cb_vft->cleanup_cb (s, 1 /* parent_died */ );
 }
@@ -348,7 +373,7 @@ echo_handle_data (echo_main_t * em, echo_session_t * s, u8 * rx_buf)
   int n_read, n_sent = 0;
 
   n_read = recv_data_chunk (em, s, rx_buf);
-  if (em->data_source == ECHO_TEST_DATA_SOURCE)
+  if ((em->data_source == ECHO_TEST_DATA_SOURCE) && s->bytes_to_send)
     n_sent = send_data_chunk (s, em->connect_test_data,
 			      s->bytes_sent % em->tx_buf_size,
 			      em->tx_buf_size);
@@ -390,8 +415,8 @@ echo_handle_data (echo_main_t * em, echo_session_t * s, u8 * rx_buf)
 	  ECHO_LOG (1, "Idle FIFOs TX:%dB RX:%dB",
 		    svm_fifo_max_dequeue (s->tx_fifo),
 		    svm_fifo_max_dequeue (s->rx_fifo));
-	  ECHO_LOG (1, "Session 0x%lx state %u", s->vpp_session_handle,
-		    s->session_state);
+	  ECHO_LOG (1, "Session 0x%lx state %U", s->vpp_session_handle,
+		    echo_format_session_state, s->session_state);
 	}
     }
 }
@@ -433,19 +458,26 @@ echo_data_thread_fn (void *arg)
 	  echo_check_closed_listener (em, s);
 	  break;
 	case ECHO_SESSION_STATE_AWAIT_CLOSING:
+	  ECHO_LOG (3, "%U: %U", echo_format_session, s,
+		    echo_format_session_state, s->session_state);
 	  echo_check_closed_listener (em, s);
 	  break;
 	case ECHO_SESSION_STATE_CLOSING:
+	  ECHO_LOG (2, "%U: %U", echo_format_session, s,
+		    echo_format_session_state, s->session_state);
 	  echo_update_count_on_session_close (em, s);
 	  em->proto_cb_vft->cleanup_cb (s, 0 /* parent_died */ );
 	  break;
 	case ECHO_SESSION_STATE_CLOSED:
+	  ECHO_LOG (2, "%U: %U", echo_format_session, s,
+		    echo_format_session_state, s->session_state);
 	  n_closed_sessions++;
 	  break;
 	}
       if (n_closed_sessions == thread_n_sessions)
 	break;
     }
+  ECHO_LOG (1, "Mission accomplished!");
   pthread_exit (0);
 }
 
@@ -456,6 +488,7 @@ session_unlisten_handler (session_unlisten_msg_t * mp)
   echo_main_t *em = &echo_main;
   listen_session = pool_elt_at_index (em->sessions, em->listen_session_index);
   em->proto_cb_vft->cleanup_cb (listen_session, 0 /* parent_died */ );
+  listen_session->session_state = ECHO_SESSION_STATE_CLOSED;
   em->state = STATE_DISCONNECTED;
 }
 
@@ -493,9 +526,13 @@ session_accepted_handler (session_accepted_msg_t * mp)
   svm_fifo_t *rx_fifo, *tx_fifo;
   echo_main_t *em = &echo_main;
   echo_session_t *session, *ls;
-  /* Allocate local session and set it up */
-  session = echo_session_new (em);
 
+  if (!(ls = echo_get_session_from_handle (em, mp->listener_handle)))
+    {
+      ECHO_FAIL (ECHO_FAIL_SESSION_ACCEPTED_BAD_LISTENER,
+		 "Unknown listener handle 0x%lx", mp->listener_handle);
+      return;
+    }
   if (wait_for_segment_allocation (mp->segment_handle))
     {
       ECHO_FAIL (ECHO_FAIL_ACCEPTED_WAIT_FOR_SEG_ALLOC,
@@ -503,6 +540,10 @@ session_accepted_handler (session_accepted_msg_t * mp)
       return;
     }
 
+  /* Allocate local session and set it up */
+  session = echo_session_new (em);
+  session->vpp_session_handle = mp->handle;
+
   rx_fifo = uword_to_pointer (mp->server_rx_fifo, svm_fifo_t *);
   rx_fifo->client_session_index = session->session_index;
   tx_fifo = uword_to_pointer (mp->server_tx_fifo, svm_fifo_t *);
@@ -524,13 +565,12 @@ session_accepted_handler (session_accepted_msg_t * mp)
   session->start = clib_time_now (&em->clib_time);
   session->vpp_evt_q = uword_to_pointer (mp->vpp_event_queue_address,
 					 svm_msg_q_t *);
-  if (!(ls = echo_get_session_from_handle (em, mp->listener_handle)))
-    return;
   session->listener_index = ls->session_index;
 
   /* Add it to lookup table */
-  ECHO_LOG (1, "Accepted session 0x%lx -> 0x%lx", mp->handle,
-	    mp->listener_handle);
+  ECHO_LOG (1, "Accepted session 0x%lx S[%u] -> 0x%lx S[%u]",
+	    mp->handle, session->session_index,
+	    mp->listener_handle, session->listener_index);
   echo_session_handle_add_del (em, mp->handle, session->session_index);
 
   app_alloc_ctrl_evt_to_vpp (session->vpp_evt_q, app_evt,
@@ -606,15 +646,21 @@ session_disconnected_handler (session_disconnected_msg_t * mp)
   session_disconnected_reply_msg_t *rmp;
   echo_main_t *em = &echo_main;
   echo_session_t *s;
-  ECHO_LOG (1, "passive close session 0x%lx", mp->handle);
   if (!(s = echo_get_session_from_handle (em, mp->handle)))
     {
-      ECHO_FAIL (ECHO_FAIL_SESSION_DISCONNECT, "Session 0x%lx not found",
-		 mp->handle);
+      ECHO_LOG (0, "Invalid vpp_session_handle: 0x%lx", mp->handle);
       return;
     }
-  em->proto_cb_vft->disconnected_cb (mp, s);
-
+  if (s->session_state == ECHO_SESSION_STATE_CLOSED)
+    {
+      ECHO_LOG (1, "%U: already in ECHO_SESSION_STATE_CLOSED",
+		echo_format_session, s);
+    }
+  else
+    {
+      ECHO_LOG (1, "%U: passive close", echo_format_session, s);
+      em->proto_cb_vft->disconnected_cb (mp, s);
+    }
   app_alloc_ctrl_evt_to_vpp (s->vpp_evt_q, app_evt,
 			     SESSION_CTRL_EVT_DISCONNECTED_REPLY);
   rmp = (session_disconnected_reply_msg_t *) app_evt->evt->data;
@@ -631,13 +677,12 @@ session_reset_handler (session_reset_msg_t * mp)
   echo_main_t *em = &echo_main;
   session_reset_reply_msg_t *rmp;
   echo_session_t *s = 0;
-  ECHO_LOG (1, "Reset session 0x%lx", mp->handle);
   if (!(s = echo_get_session_from_handle (em, mp->handle)))
     {
-      ECHO_FAIL (ECHO_FAIL_SESSION_RESET, "Session 0x%lx not found",
-		 mp->handle);
+      ECHO_LOG (0, "Invalid vpp_session_handle: 0x%lx", mp->handle);
       return;
     }
+  ECHO_LOG (1, "%U: session reset", echo_format_session, s);
   em->proto_cb_vft->reset_cb (mp, s);
 
   app_alloc_ctrl_evt_to_vpp (s->vpp_evt_q, app_evt,
@@ -779,6 +824,7 @@ server_run (echo_main_t * em)
   ECHO_LOG (1, "App is ready");
   echo_process_rpcs (em);
   /* Cleanup */
+  ECHO_LOG (1, "Unbind listen port");
   ls = pool_elt_at_index (em->sessions, em->listen_session_index);
   echo_send_unbind (em, ls);
   if (wait_for_state_change (em, STATE_DISCONNECTED, TIMEOUT))
@@ -821,6 +867,8 @@ print_usage_and_exit (void)
 	   "                       sconnected  - last Stream got connected\n"
 	   "                       lastbyte    - Last expected byte received\n"
 	   "                       exit        - Exiting of the app\n"
+	   "  rx-results-diff     Rx results different to pass test\n"
+	   "  tx-results-diff     Tx results different to pass test\n"
 	   "  json                Output global stats in json\n"
 	   "  log=N               Set the log level to [0: no output, 1:errors, 2:log]\n"
 	   "\n"
@@ -837,7 +885,7 @@ print_usage_and_exit (void)
   fprintf (stderr, "\nDefault configuration is :\n"
 	   " server nclients 1/1 RX=64Kb TX=RX\n"
 	   " client nclients 1/1 RX=64Kb TX=64Kb\n");
-  exit (1);
+  exit (ECHO_FAIL_USAGE);
 }
 
 static int
@@ -937,6 +985,10 @@ echo_process_opts (int argc, char **argv)
 	;
       else if (unformat (a, "RX=%U", unformat_data, &em->bytes_to_receive))
 	;
+      else if (unformat (a, "rx-results-diff"))
+	em->rx_results_diff = 1;
+      else if (unformat (a, "tx-results-diff"))
+	em->tx_results_diff = 1;
       else if (unformat (a, "json"))
 	em->output_json = 1;
       else if (unformat (a, "log=%d", &em->log_lvl))
@@ -1146,7 +1198,6 @@ main (int argc, char **argv)
     clients_run (em);
   echo_notify_event (em, ECHO_EVT_EXIT);
   echo_free_sessions (em);
-  echo_assert_test_suceeded (em);
   echo_send_detach (em);
   if (wait_for_state_change (em, STATE_DETACHED, TIMEOUT))
     {
@@ -1164,6 +1215,7 @@ main (int argc, char **argv)
     vl_socket_client_disconnect ();
   else
     vl_client_disconnect_from_vlib ();
+  echo_assert_test_suceeded (em);
 exit_on_error:
   ECHO_LOG (0, "Test complete !\n");
   if (em->output_json)
diff --git a/src/plugins/hs_apps/sapi/vpp_echo_bapi.c b/src/plugins/hs_apps/sapi/vpp_echo_bapi.c
index a565a91899a..fad0d18ccc6 100644
--- a/src/plugins/hs_apps/sapi/vpp_echo_bapi.c
+++ b/src/plugins/hs_apps/sapi/vpp_echo_bapi.c
@@ -283,7 +283,11 @@ vl_api_app_attach_reply_t_handler (vl_api_app_attach_reply_t * mp)
       return;
     }
 
-  ASSERT (mp->app_mq);
+  if (!mp->app_mq)
+    {
+      ECHO_FAIL (ECHO_FAIL_VL_API_NULL_APP_MQ, "NULL app_mq");
+      return;
+    }
   em->app_mq = uword_to_pointer (mp->app_mq, svm_msg_q_t *);
   em->ctrl_mq = uword_to_pointer (mp->vpp_ctrl_mq, svm_msg_q_t *);
 
diff --git a/src/plugins/hs_apps/sapi/vpp_echo_common.c b/src/plugins/hs_apps/sapi/vpp_echo_common.c
index 0f6c2ec7135..dbe8d92661f 100644
--- a/src/plugins/hs_apps/sapi/vpp_echo_common.c
+++ b/src/plugins/hs_apps/sapi/vpp_echo_common.c
@@ -167,29 +167,82 @@ init_error_string_table ()
 }
 
 u8 *
+echo_format_session (u8 * s, va_list * args)
+{
+  echo_session_t *session = va_arg (*args, echo_session_t *);
+
+  return format (s, "%U 0x%lx S[%u]", echo_format_session_type,
+		 session->session_type, session->vpp_session_handle,
+		 session->session_index);
+}
+
+u8 *
+echo_format_session_type (u8 * s, va_list * args)
+{
+  u32 session_type = va_arg (*args, u32);
+  switch (session_type)
+    {
+    case ECHO_SESSION_TYPE_QUIC:
+      return format (s, "Qsession");
+    case ECHO_SESSION_TYPE_STREAM:
+      return format (s, "Stream");
+    case ECHO_SESSION_TYPE_LISTEN:
+      return format (s, "Lsession");
+    default:
+      break;
+    }
+  return format (s, "BadSession");
+}
+
+u8 *
+echo_format_session_state (u8 * s, va_list * args)
+{
+  u32 session_state = va_arg (*args, u32);
+  switch (session_state)
+    {
+    case ECHO_SESSION_STATE_INITIAL:
+      return format (s, "ECHO_SESSION_STATE_INITIAL (%u)", session_state);
+    case ECHO_SESSION_STATE_READY:
+      return format (s, "ECHO_SESSION_STATE_READY (%u)", session_state);
+    case ECHO_SESSION_STATE_AWAIT_CLOSING:
+      return format (s, "ECHO_SESSION_STATE_AWAIT_CLOSING (%u)",
+		     session_state);
+    case ECHO_SESSION_STATE_AWAIT_DATA:
+      return format (s, "ECHO_SESSION_STATE_AWAIT_DATA (%u)", session_state);
+    case ECHO_SESSION_STATE_CLOSING:
+      return format (s, "ECHO_SESSION_STATE_CLOSING (%u)", session_state);
+    case ECHO_SESSION_STATE_CLOSED:
+      return format (s, "ECHO_SESSION_STATE_CLOSED (%u)", session_state);
+    default:
+      break;
+    }
+  return format (s, "unknown session state (%u)", session_state);
+}
+
+u8 *
 echo_format_app_state (u8 * s, va_list * args)
 {
   u32 state = va_arg (*args, u32);
   if (state == STATE_START)
-    return format (s, "STATE_START");
+    return format (s, "STATE_START (%u)", state);
   if (state == STATE_ATTACHED)
-    return format (s, "STATE_ATTACHED");
+    return format (s, "STATE_ATTACHED (%u)", state);
   if (state == STATE_ATTACHED_NO_CERT)
-    return format (s, "STATE_ATTACHED_NO_CERT");
+    return format (s, "STATE_ATTACHED_NO_CERT (%u)", state);
   if (state == STATE_ATTACHED_ONE_CERT)
-    return format (s, "STATE_ATTACHED_ONE_CERT");
+    return format (s, "STATE_ATTACHED_ONE_CERT (%u)", state);
   if (state == STATE_LISTEN)
-    return format (s, "STATE_LISTEN");
+    return format (s, "STATE_LISTEN (%u)", state);
   if (state == STATE_READY)
-    return format (s, "STATE_READY");
+    return format (s, "STATE_READY (%u)", state);
   if (state == STATE_DATA_DONE)
-    return format (s, "STATE_DATA_DONE");
+    return format (s, "STATE_DATA_DONE (%u)", state);
   if (state == STATE_DISCONNECTED)
-    return format (s, "STATE_DISCONNECTED");
+    return format (s, "STATE_DISCONNECTED (%u)", state);
   if (state == STATE_DETACHED)
-    return format (s, "STATE_DETACHED");
+    return format (s, "STATE_DETACHED (%u)", state);
   else
-    return format (s, "unknown state");
+    return format (s, "unknown state (%u)", state);
 }
 
 uword
@@ -475,9 +528,15 @@ echo_session_handle_add_del (echo_main_t * em, u64 handle, u32 sid)
 {
   clib_spinlock_lock (&em->sid_vpp_handles_lock);
   if (sid == SESSION_INVALID_INDEX)
-    hash_unset (em->session_index_by_vpp_handles, handle);
+    {
+      ECHO_LOG (2, "hash_unset(0x%lx)", handle);
+      hash_unset (em->session_index_by_vpp_handles, handle);
+    }
   else
-    hash_set (em->session_index_by_vpp_handles, handle, sid);
+    {
+      ECHO_LOG (2, "hash_set(0x%lx) S[%d]", handle, sid);
+      hash_set (em->session_index_by_vpp_handles, handle, sid);
+    }
   clib_spinlock_unlock (&em->sid_vpp_handles_lock);
 }
 
@@ -525,8 +584,7 @@ echo_get_session_from_handle (echo_main_t * em, u64 handle)
   clib_spinlock_unlock (&em->sid_vpp_handles_lock);
   if (!p)
     {
-      ECHO_FAIL (ECHO_FAIL_GET_SESSION_FROM_HANDLE,
-		 "unknown handle 0x%lx", handle);
+      ECHO_LOG (1, "unknown handle 0x%lx", handle);
       return 0;
     }
   return pool_elt_at_index (em->sessions, p[0]);
diff --git a/src/plugins/hs_apps/sapi/vpp_echo_common.h b/src/plugins/hs_apps/sapi/vpp_echo_common.h
index ea20e2b9e09..a7010d85cb7 100644
--- a/src/plugins/hs_apps/sapi/vpp_echo_common.h
+++ b/src/plugins/hs_apps/sapi/vpp_echo_common.h
@@ -39,12 +39,15 @@
 
 #define foreach_echo_fail_code                                          \
   _(ECHO_FAIL_NONE, "ECHO_FAIL_NONE")                                   \
+  _(ECHO_FAIL_USAGE, "ECHO_FAIL_USAGE")                                 \
   _(ECHO_FAIL_SEND_IO_EVT, "ECHO_FAIL_SEND_IO_EVT")                     \
   _(ECHO_FAIL_SOCKET_CONNECT, "ECHO_FAIL_SOCKET_CONNECT")               \
   _(ECHO_FAIL_INIT_SHM_API, "ECHO_FAIL_INIT_SHM_API")                   \
   _(ECHO_FAIL_SHMEM_CONNECT, "ECHO_FAIL_SHMEM_CONNECT")                 \
   _(ECHO_FAIL_TEST_BYTES_ERR, "ECHO_FAIL_TEST_BYTES_ERR")               \
   _(ECHO_FAIL_BIND, "ECHO_FAIL_BIND")                                   \
+  _(ECHO_FAIL_SESSION_ACCEPTED_BAD_LISTENER,                            \
+    "ECHO_FAIL_SESSION_ACCEPTED_BAD_LISTENER")                          \
   _(ECHO_FAIL_ACCEPTED_WAIT_FOR_SEG_ALLOC,                              \
     "ECHO_FAIL_ACCEPTED_WAIT_FOR_SEG_ALLOC")                            \
   _(ECHO_FAIL_SESSION_CONNECT, "ECHO_FAIL_SESSION_CONNECT")             \
@@ -65,6 +68,7 @@
   _(ECHO_FAIL_VL_API_APP_ATTACH, "ECHO_FAIL_VL_API_APP_ATTACH")         \
   _(ECHO_FAIL_VL_API_MISSING_SEGMENT_NAME,                              \
     "ECHO_FAIL_VL_API_MISSING_SEGMENT_NAME")                            \
+  _(ECHO_FAIL_VL_API_NULL_APP_MQ, "ECHO_FAIL_VL_API_NULL_APP_MQ")       \
   _(ECHO_FAIL_VL_API_RECV_FD_MSG, "ECHO_FAIL_VL_API_RECV_FD_MSG")       \
   _(ECHO_FAIL_VL_API_SVM_FIFO_SEG_ATTACH,                               \
     "ECHO_FAIL_VL_API_SVM_FIFO_SEG_ATTACH")                             \
@@ -101,15 +105,24 @@ typedef enum
 
 extern char *echo_fail_code_str[];
 
-#define CHECK(fail, expected, result, _fmt, _args...)                   \
-    if (expected != result)                                             \
-      ECHO_FAIL (fail, "expected %d, got %d : " _fmt, expected,         \
-                 result, ##_args);                                      \
+#define CHECK_SAME(fail, expected, result, _fmt, _args...)      \
+do {                                                            \
+  if ((expected) != (result))                                   \
+    ECHO_FAIL ((fail), "expected same (%d, got %d) : "_fmt,     \
+               (expected), (result), ##_args);                  \
+} while (0)
+
+#define CHECK_DIFF(fail, expected, result, _fmt, _args...)      \
+do {                                                            \
+  if ((expected) == (result))                                   \
+    ECHO_FAIL ((fail), "expected different (both %d) : "_fmt,   \
+               (expected), ##_args);                            \
+} while (0)
 
 #define ECHO_FAIL(fail, _fmt, _args...)                                 \
-  {                                                                     \
+do {                                                                    \
     echo_main_t *em = &echo_main;                                       \
-    em->has_failed = fail;                                              \
+    em->has_failed = (fail);                                            \
     if (vec_len(em->fail_descr))                                        \
       em->fail_descr = format(em->fail_descr, " | %s (%d): "_fmt,       \
                               echo_fail_code_str[fail], fail, ##_args); \
@@ -119,7 +132,7 @@ extern char *echo_fail_code_str[];
     em->time_to_stop = 1;                                               \
     if (em->log_lvl > 0)                                                \
       clib_warning ("%v", em->fail_descr);                              \
-  }
+} while (0)
 
 #define ECHO_LOG(lvl, _fmt,_args...)    \
   {                                     \
@@ -270,6 +283,8 @@ typedef struct
   /* State of the connection, shared between msg RX thread and main thread */
   volatile connection_state_t state;
   volatile u8 time_to_stop;	/* Signal variables */
+  u8 rx_results_diff;		/* Rx results will be different than cfg */
+  u8 tx_results_diff;		/* Tx results will be different than cfg */
   u8 has_failed;		/* stores the exit code */
   u8 *fail_descr;		/* vector containing fail description */
 
@@ -359,6 +374,9 @@ u8 *format_ip46_address (u8 * s, va_list * args);
 uword unformat_data (unformat_input_t * input, va_list * args);
 u8 *format_api_error (u8 * s, va_list * args);
 void init_error_string_table ();
+u8 *echo_format_session (u8 * s, va_list * args);
+u8 *echo_format_session_type (u8 * s, va_list * args);
+u8 *echo_format_session_state (u8 * s, va_list * args);
 u8 *echo_format_app_state (u8 * s, va_list * args);
 uword echo_unformat_close (unformat_input_t * input, va_list * args);
 uword echo_unformat_timing_event (unformat_input_t * input, va_list * args);
diff --git a/src/plugins/hs_apps/sapi/vpp_echo_proto_quic.c b/src/plugins/hs_apps/sapi/vpp_echo_proto_quic.c
index 999cacb5353..a78f949a0ef 100644
--- a/src/plugins/hs_apps/sapi/vpp_echo_proto_quic.c
+++ b/src/plugins/hs_apps/sapi/vpp_echo_proto_quic.c
@@ -60,8 +60,8 @@ quic_echo_on_connected_connect (session_connected_msg_t * mp,
   for (i = 0; i < eqm->n_stream_clients; i++)
     echo_send_rpc (em, echo_send_connect, (void *) mp->handle, session_index);
 
-  ECHO_LOG (0, "Qsession 0x%llx connected to %U:%d",
-	    mp->handle, format_ip46_address, &mp->lcl.ip,
+  ECHO_LOG (0, "Qsession 0x%llx S[%d] connected to %U:%d",
+	    mp->handle, session_index, format_ip46_address, &mp->lcl.ip,
 	    mp->lcl.is_ip4, clib_net_to_host_u16 (mp->lcl.port));
 }
 
@@ -106,7 +106,7 @@ quic_echo_on_accept_connect (session_accepted_msg_t * mp, u32 session_index)
 {
   echo_main_t *em = &echo_main;
   quic_echo_proto_main_t *eqm = &quic_echo_proto_main;
-  ECHO_LOG (1, "Accept on QSession 0x%lx %u", mp->handle);
+  ECHO_LOG (1, "Accept on QSession 0x%lx S[%u]", mp->handle, session_index);
   u32 i;
 
   echo_notify_event (em, ECHO_EVT_FIRST_SCONNECT);
@@ -118,8 +118,8 @@ static void
 quic_echo_on_accept_error (session_accepted_msg_t * mp, u32 session_index)
 {
   ECHO_FAIL (ECHO_FAIL_QUIC_WRONG_ACCEPT,
-	     "Got a wrong accept on session %u [%lx]", session_index,
-	     mp->handle);
+	     "Got a wrong accept on session 0x%lx S[%u]", mp->handle,
+	     session_index);
 }
 
 static void
@@ -164,7 +164,12 @@ quic_echo_cleanup_listener (u32 listener_index, echo_main_t * em,
 {
   echo_session_t *ls;
   ls = pool_elt_at_index (em->sessions, listener_index);
-  ASSERT (ls->session_type == ECHO_SESSION_TYPE_QUIC);
+  if (ls->session_type != ECHO_SESSION_TYPE_QUIC)
+    {
+      ECHO_LOG (1, "%U: Invalid listener session type",
+		echo_format_session, ls);
+      return;
+    }
   if (!clib_atomic_sub_fetch (&ls->accepted_session_count, 1))
     {
       if (eqm->send_quic_disconnects == ECHO_CLOSE_F_ACTIVE)
@@ -186,7 +191,12 @@ quic_echo_cleanup_cb (echo_session_t * s, u8 parent_died)
 {
   echo_main_t *em = &echo_main;
   quic_echo_proto_main_t *eqm = &quic_echo_proto_main;
-  ASSERT (s->session_state < ECHO_SESSION_STATE_CLOSED);
+  if ((em->state == STATE_DATA_DONE) ||
+      !(s->session_state < ECHO_SESSION_STATE_CLOSED))
+    return;
+  ECHO_LOG (2, "%U cleanup (parent_died %d)", echo_format_session, s,
+	    parent_died);
+  s->session_state = ECHO_SESSION_STATE_CLOSED;
   if (s->session_type == ECHO_SESSION_TYPE_QUIC)
     {
       if (parent_died)
@@ -202,12 +212,11 @@ quic_echo_cleanup_cb (echo_session_t * s, u8 parent_died)
 	quic_echo_cleanup_listener (s->listener_index, em, eqm);
       clib_atomic_sub_fetch (&em->n_clients_connected, 1);
     }
-
-  ECHO_LOG (1, "Cleanup sessions (still %uQ %uS)",
-	    eqm->n_quic_clients_connected, em->n_clients_connected);
-  s->session_state = ECHO_SESSION_STATE_CLOSED;
   if (!em->n_clients_connected && !eqm->n_quic_clients_connected)
     em->state = STATE_DATA_DONE;
+  ECHO_LOG (1, "Cleanup sessions (still %uQ %uS): app %U",
+	    eqm->n_quic_clients_connected, em->n_clients_connected,
+	    echo_format_app_state, em->state);
 }
 
 static void
@@ -225,18 +234,19 @@ quic_echo_initiate_qsession_close_no_stream (echo_main_t * em)
       {
         if (eqm->send_quic_disconnects == ECHO_CLOSE_F_ACTIVE)
           {
-            ECHO_LOG (1,"ACTIVE close 0x%lx", s->vpp_session_handle);
-            echo_send_rpc (em, echo_send_disconnect_session, (void *) s->vpp_session_handle, 0);
+            ECHO_LOG (1,"%U: ACTIVE close", echo_format_session, s);
+            echo_send_rpc (em, echo_send_disconnect_session,
+                           (void *) s->vpp_session_handle, 0);
             clib_atomic_fetch_add (&em->stats.active_count.q, 1);
           }
         else if (eqm->send_quic_disconnects == ECHO_CLOSE_F_NONE)
           {
-            ECHO_LOG (1,"Discard close 0x%lx", s->vpp_session_handle);
+            ECHO_LOG (1,"%U: CLEAN close", echo_format_session, s);
             quic_echo_cleanup_cb (s, 0 /* parent_died */);
             clib_atomic_fetch_add (&em->stats.clean_count.q, 1);
           }
         else
-          ECHO_LOG (1,"Passive close 0x%lx", s->vpp_session_handle);
+          ECHO_LOG (1,"%U: PASSIVE close", echo_format_session, s);
       }
   }));
   /* *INDENT-ON* */
@@ -249,10 +259,11 @@ quic_echo_on_connected (session_connected_msg_t * mp, u32 session_index)
   quic_echo_proto_main_t *eqm = &quic_echo_proto_main;
   echo_session_t *listen_session;
   echo_session_t *session = pool_elt_at_index (em->sessions, session_index);
+
   if (session->listener_index == SESSION_INVALID_INDEX)
     {
-      ECHO_LOG (1, "Connected session 0x%lx -> URI", mp->handle);
       session->session_type = ECHO_SESSION_TYPE_QUIC;
+      ECHO_LOG (1, "Connected %U -> URI", echo_format_session, session);
       session->accepted_session_count = 0;
       if (eqm->cb_vft.quic_connected_cb)
 	eqm->cb_vft.quic_connected_cb (mp, session->session_index);
@@ -262,10 +273,10 @@ quic_echo_on_connected (session_connected_msg_t * mp, u32 session_index)
     {
       listen_session =
 	pool_elt_at_index (em->sessions, session->listener_index);
-      ECHO_LOG (1, "Connected session 0x%lx -> 0x%lx", mp->handle,
-		listen_session->vpp_session_handle);
       session->session_type = ECHO_SESSION_TYPE_STREAM;
       clib_atomic_fetch_add (&listen_session->accepted_session_count, 1);
+      ECHO_LOG (1, "Connected %U -> %U", echo_format_session, session,
+		echo_format_session, listen_session);
       if (em->i_am_master && eqm->cb_vft.server_stream_connected_cb)
 	eqm->cb_vft.server_stream_connected_cb (mp, session->session_index);
       if (!em->i_am_master && eqm->cb_vft.client_stream_connected_cb)
@@ -295,14 +306,14 @@ quic_echo_retry_connect (u32 session_index)
   echo_main_t *em = &echo_main;
   if (session_index == SESSION_INVALID_INDEX)
     {
-      ECHO_LOG (1, "Retrying connect %s", em->uri);
+      ECHO_LOG (1, "Retrying Qsession connect");
       echo_send_rpc (em, echo_send_connect, (void *) SESSION_INVALID_HANDLE,
 		     SESSION_INVALID_INDEX);
     }
   else
     {
       session = pool_elt_at_index (em->sessions, session_index);
-      ECHO_LOG (1, "Retrying connect 0x%lx", session->vpp_session_handle);
+      ECHO_LOG (1, "Retrying connect %U", echo_format_session, session);
       echo_send_rpc (em, echo_send_connect,
 		     (void *) session->vpp_session_handle, session_index);
     }