From ff5a9b6ecd744ff5c42e6c2388dd31a338ea6a0c Mon Sep 17 00:00:00 2001 From: Dave Wallace Date: Wed, 25 Sep 2019 17:58:24 -0400 Subject: 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 Change-Id: I9d0075fcb18e20829f420da104d69523897b0552 --- src/plugins/hs_apps/sapi/vpp_echo.c | 124 +++++++++++++++++++++++++----------- 1 file changed, 88 insertions(+), 36 deletions(-) (limited to 'src/plugins/hs_apps/sapi/vpp_echo.c') 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) -- cgit 1.2.3-korg