X-Git-Url: https://gerrit.fd.io/r/gitweb?a=blobdiff_plain;f=src%2Fvcl%2Fvppcom.c;h=aff81f5351ea466a220371d785c39fd3f76a6897;hb=d3046598b0954f20031852ad55bcf2d4900c01bf;hp=2e3af1b352637df0fbc4dd8401dbf454920d1274;hpb=9c5161aedff8e271cc036faeab58b665a3c8105e;p=vpp.git diff --git a/src/vcl/vppcom.c b/src/vcl/vppcom.c index 2e3af1b3526..aff81f5351e 100644 --- a/src/vcl/vppcom.c +++ b/src/vcl/vppcom.c @@ -23,6 +23,7 @@ #include #include #include +#include #define vl_typedefs /* define message structures */ #include @@ -107,7 +108,7 @@ typedef struct u32 sm_seg_index; u32 client_context; u64 vpp_handle; - unix_shared_memory_queue_t *vpp_event_queue; + svm_queue_t *vpp_event_queue; /* Socket configuration state */ /* TBD: covert 'is_*' vars to bit in u8 flags; */ @@ -127,6 +128,7 @@ typedef struct u8 proto; u64 client_queue_address; u64 options[16]; + elog_track_t elog_track; } session_t; typedef struct vppcom_cfg_t_ @@ -150,6 +152,8 @@ typedef struct vppcom_cfg_t_ f64 app_timeout; f64 session_timeout; f64 accept_timeout; + u32 event_ring_size; + char *event_log_path; } vppcom_cfg_t; typedef struct vppcom_main_t_ @@ -160,7 +164,7 @@ typedef struct vppcom_main_t_ int main_cpu; /* vpe input queue */ - unix_shared_memory_queue_t *vl_input_queue; + svm_queue_t *vl_input_queue; /* API client handle */ u32 my_client_index; @@ -178,7 +182,7 @@ typedef struct vppcom_main_t_ clib_bitmap_t *ex_bitmap; /* Our event queue */ - unix_shared_memory_queue_t *app_event_queue; + svm_queue_t *app_event_queue; /* unique segment name counter */ u32 unique_segment_index; @@ -191,6 +195,10 @@ typedef struct vppcom_main_t_ vppcom_cfg_t cfg; + /* Event logging */ + elog_main_t elog_main; + elog_track_t elog_track; + /* VNET_API_ERROR_FOO -> "Foo" hash table */ uword *error_string_by_error_number; } vppcom_main_t; @@ -355,10 +363,31 @@ vppcom_session_table_del_listener (u64 listener_handle) hash_unset (vcm->session_index_by_vpp_handles, listener_handle); } +static void +write_elog (void) +{ + elog_main_t *em = &vcm->elog_main; + char *chroot_file; + clib_error_t *error = 0; + + chroot_file = + (char *) format (0, "%s/%d-%d-vcl-elog%c", vcm->cfg.event_log_path, + vcm->my_client_index, getpid (), 0); + error = elog_write_file (em, chroot_file, 1 /* flush ring */ ); + if (error) + { + clib_error_report (error); + } + if (VPPCOM_DEBUG > 0) + clib_warning ("[%d] Event Log:'%s' ", getpid (), chroot_file); + +} + static int vppcom_connect_to_vpp (char *app_name) { api_main_t *am = &api_main; + int rv = VPPCOM_OK; if (VPPCOM_DEBUG > 0) printf ("\nConnecting to VPP api..."); @@ -366,16 +395,49 @@ vppcom_connect_to_vpp (char *app_name) vcm->cfg.vpp_api_q_length) < 0) { clib_warning ("[%d] connect to vpp (%s) failed!", getpid (), app_name); - return VPPCOM_ECONNREFUSED; + rv = VPPCOM_ECONNREFUSED; + } + else + { + + vcm->vl_input_queue = am->shmem_hdr->vl_input_queue; + vcm->my_client_index = am->my_client_index; + vcm->app_state = STATE_APP_CONN_VPP; + + if (VPPCOM_DEBUG > 0) + printf (" connected!\n"); } - vcm->vl_input_queue = am->shmem_hdr->vl_input_queue; - vcm->my_client_index = am->my_client_index; if (VPPCOM_DEBUG > 0) - printf (" connected!\n"); + { + vcm->elog_main.lock = + clib_mem_alloc_aligned (CLIB_CACHE_LINE_BYTES, CLIB_CACHE_LINE_BYTES); + vcm->elog_main.lock[0] = 0; + vcm->elog_main.event_ring_size = vcm->cfg.event_ring_size; + elog_init (&vcm->elog_main, vcm->elog_main.event_ring_size); + elog_enable_disable (&vcm->elog_main, 1); + + vcm->elog_track.name = + (char *) format (0, "P:%d:C:%d%c", getpid (), + vcm->my_client_index, 0); + elog_track_register (&vcm->elog_main, &vcm->elog_track); - vcm->app_state = STATE_APP_CONN_VPP; - return VPPCOM_OK; + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "connect_vpp:rv:%d", + .format_args = "i4", + }; + struct + { + u32 data; + } *ed; + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, vcm->elog_track); + ed->data = rv; + /* *INDENT-ON* */ + } + + return rv; } static u8 * @@ -418,6 +480,26 @@ vppcom_wait_for_app_state_change (app_state_t app_state) if (VPPCOM_DEBUG > 0) clib_warning ("[%d] timeout waiting for state %s (%d)", getpid (), vppcom_app_state_str (app_state), app_state); + + if (VPPCOM_DEBUG > 0) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "ERR: timeout state:%d", + .format_args = "i4", + }; + struct + { + u32 data; + } *ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, vcm->elog_track); + + ed->data = app_state; + /* *INDENT-ON* */ + } + return VPPCOM_ETIMEDOUT; } @@ -457,6 +539,26 @@ vppcom_wait_for_session_state_change (u32 session_index, if (VPPCOM_DEBUG > 0) clib_warning ("[%d] timeout waiting for state 0x%x (%s)", getpid (), state, vppcom_session_state_str (state)); + + if (VPPCOM_DEBUG > 0) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "ERR: timeout state:%d", + .format_args = "i4", + }; + struct + { + u32 data; + } *ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + + ed->data = state; + /* *INDENT-ON* */ + } + return VPPCOM_ETIMEDOUT; } @@ -477,6 +579,26 @@ vppcom_wait_for_client_session_index (f64 wait_for_time) if (VPPCOM_DEBUG > 0) clib_warning ("[%d] timeout waiting for client_session_index", getpid ()); + + if (VPPCOM_DEBUG > 0) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "ERR: timeout waiting for session index :%d", + .format_args = "i4", + }; + struct + { + u32 data; + } *ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, vcm->elog_track); + + ed->data = getpid(); + /* *INDENT-ON* */ + } + return VPPCOM_ETIMEDOUT; } @@ -637,8 +759,7 @@ vl_api_application_attach_reply_t_handler (vl_api_application_attach_reply_t * } vcm->app_event_queue = - uword_to_pointer (mp->app_event_queue_address, - unix_shared_memory_queue_t *); + uword_to_pointer (mp->app_event_queue_address, svm_queue_t *); vcm->app_state = STATE_APP_ATTACHED; } @@ -838,7 +959,7 @@ done: */ session->is_cut_thru = is_cut_thru; session->vpp_event_queue = uword_to_pointer (mp->vpp_event_queue_address, - unix_shared_memory_queue_t *); + svm_queue_t *); rx_fifo = uword_to_pointer (mp->server_rx_fifo, svm_fifo_t *); rx_fifo->client_session_index = session_index; @@ -1122,7 +1243,7 @@ vl_api_accept_session_t_handler (vl_api_accept_session_t * mp) session->server_rx_fifo = rx_fifo; session->server_tx_fifo = tx_fifo; session->vpp_event_queue = uword_to_pointer (mp->vpp_event_queue_address, - unix_shared_memory_queue_t *); + svm_queue_t *); session->state = STATE_ACCEPT; session->is_cut_thru = 0; session->is_server = 1; @@ -1147,6 +1268,46 @@ vl_api_accept_session_t_handler (vl_api_accept_session_t * mp) mp->handle, session_index, mp->is_ip4 ? "IPv4" : "IPv6", format_ip46_address, &mp->ip, mp->is_ip4, clib_net_to_host_u16 (mp->port), session->vpp_event_queue); + + if (VPPCOM_DEBUG > 0) + { + session->elog_track.name = + (char *) format (0, "C:%d:S:%d%c", vcm->my_client_index, + session_index, 0); + elog_track_register (&vcm->elog_main, &session->elog_track); + + if (session->peer_addr.is_ip4) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = + "client_accept:handle:%x addr:%d.%d.%d.%d:%d", + .format_args = "i8i1i1i1i1i2", + }; + + CLIB_PACKED (struct { + u64 handle; //8 + u8 addr[4]; //4 + u16 port; //2 + }) * ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + + ed->handle = mp->handle; + ed->addr[0] = session->peer_addr.ip46.ip4.as_u8[0]; + ed->addr[1] = session->peer_addr.ip46.ip4.as_u8[1]; + ed->addr[2] = session->peer_addr.ip46.ip4.as_u8[2]; + ed->addr[3] = session->peer_addr.ip46.ip4.as_u8[3]; + ed->port = session->peer_port; + /* *INDENT-ON* */ + } + else + { + clib_warning ("ip6"); + } + } + } static void @@ -1155,7 +1316,7 @@ vppcom_send_connect_session_reply (session_t * session, u32 session_index, { vl_api_connect_session_reply_t *rmp; u32 len; - unix_shared_memory_queue_t *client_q; + svm_queue_t *client_q; rmp = vl_msg_api_alloc (sizeof (*rmp)); memset (rmp, 0, sizeof (*rmp)); @@ -1185,8 +1346,7 @@ vppcom_send_connect_session_reply (session_t * session, u32 session_index, sizeof (rmp->lcl_ip)); rmp->is_ip4 = session->peer_addr.is_ip4; rmp->lcl_port = session->peer_port; - client_q = uword_to_pointer (session->client_queue_address, - unix_shared_memory_queue_t *); + client_q = uword_to_pointer (session->client_queue_address, svm_queue_t *); ASSERT (client_q); vl_msg_api_send_shmem (client_q, (u8 *) & rmp); } @@ -1240,6 +1400,33 @@ vl_api_connect_sock_t_handler (vl_api_connect_sock_t * mp) clib_warning ("[%d] sid %u: Got a cut-thru connect request! " "clib_fifo_elts %u!\n", getpid (), session_index, clib_fifo_elts (vcm->client_session_index_fifo)); + + if (VPPCOM_DEBUG > 0) + { + session->elog_track.name = + (char *) format (0, "C:%d:S:%d%c", vcm->my_client_index, + session_index, 0); + elog_track_register (&vcm->elog_main, &session->elog_track); + + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "cut-thru-connect:S:%d clib_fifo_elts:%d", + .format_args = "i4i4", + }; + + struct + { + u32 data[2]; + } *ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + + ed->data[0] = session_index; + ed->data[1] = clib_fifo_elts (vcm->client_session_index_fifo); + /* *INDENT-ON* */ + } + clib_spinlock_unlock (&vcm->sessions_lockp); } @@ -1301,6 +1488,24 @@ vppcom_session_unbind (u32 session_index) getpid (), vpp_handle, session_index, session->state, vppcom_session_state_str (session->state)); + if (VPPCOM_DEBUG > 0) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "unbind: handle:%x", + .format_args = "i8", + }; + + struct + { + u64 handle; + } *ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + ed->handle = vpp_handle; + /* *INDENT-ON* */ + } vppcom_send_unbind_sock (vpp_handle); done: @@ -1466,6 +1671,8 @@ vppcom_cfg_init (vppcom_cfg_t * vcl_cfg) vcl_cfg->app_timeout = 10 * 60.0; vcl_cfg->session_timeout = 10 * 60.0; vcl_cfg->accept_timeout = 60.0; + vcl_cfg->event_ring_size = (128 << 10); + vcl_cfg->event_log_path = "/dev/shm"; } static void @@ -2104,6 +2311,24 @@ vppcom_app_destroy (void) clib_warning ("[%d] detaching from VPP, my_client_index %d (0x%x)", getpid (), vcm->my_client_index, vcm->my_client_index); + if (VPPCOM_DEBUG > 0) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "app_detach:C:%d", + .format_args = "i4", + }; + + struct + { + u32 data; + } *ed; + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, vcm->elog_track); + ed->data = vcm->my_client_index; + /* *INDENT-ON* */ + } + vppcom_app_detach (); rv = vppcom_wait_for_app_state_change (STATE_APP_ENABLED); if (PREDICT_FALSE (rv)) @@ -2112,6 +2337,11 @@ vppcom_app_destroy (void) clib_warning ("[%d] application detach timed out! returning %d (%s)", getpid (), rv, vppcom_retval_str (rv)); } + + /* Finished with logging before client gets reset to ~0 */ + if (VPPCOM_DEBUG > 0) + write_elog (); + vl_client_disconnect_from_vlib (); vcm->my_client_index = ~0; vcm->app_state = STATE_APP_START; @@ -2138,6 +2368,33 @@ vppcom_session_create (u32 vrf, u8 proto, u8 is_nonblocking) if (VPPCOM_DEBUG > 0) clib_warning ("[%d] sid %u", getpid (), session_index); + if (VPPCOM_DEBUG > 0) + { + session->elog_track.name = + (char *) format (0, "C:%d:S:%d%c", vcm->my_client_index, + session_index, 0); + elog_track_register (&vcm->elog_main, &session->elog_track); + + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "session_create:vrf:%d proto:%d state:%d is_nonblocking:%d", + .format_args = "i4i4i4i4", + }; + + struct + { + u32 data[4]; + } *ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + ed->data[0] = session->vrf; + ed->data[1] = session->proto; + ed->data[2] = session->state; + ed->data[3] = session->is_nonblocking; + /* *INDENT-ON* */ + } + return (int) session_index; } @@ -2251,6 +2508,26 @@ vppcom_session_close (uint32_t session_index) getpid (), vpp_handle, session_index); } done: + + if (VPPCOM_DEBUG > 0) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "session_close:rv:%d", + .format_args = "i4", + }; + + struct + { + u32 data; + } *ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + ed->data = rv; + /* *INDENT-ON* */ + } + return rv; } @@ -2288,6 +2565,36 @@ vppcom_session_bind (uint32_t session_index, vppcom_endpt_t * ep) clib_net_to_host_u16 (session->lcl_port), session->proto ? "UDP" : "TCP"); + if (VPPCOM_DEBUG > 0) + { + if (session->lcl_addr.is_ip4) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "bind local:%s:%d.%d.%d.%d:%d ", + .format_args = "t1i1i1i1i1i2", + .n_enum_strings = 2, + .enum_strings = {"TCP", "UDP",}, + }; + + CLIB_PACKED (struct { + u8 proto; + u8 addr[4]; + u16 port; + }) * ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, session->elog_track); + ed->proto = session->proto; + ed->addr[0] = session->lcl_addr.ip46.ip4.as_u8[0]; + ed->addr[1] = session->lcl_addr.ip46.ip4.as_u8[1]; + ed->addr[2] = session->lcl_addr.ip46.ip4.as_u8[2]; + ed->addr[3] = session->lcl_addr.ip46.ip4.as_u8[3]; + ed->port = clib_net_to_host_u16 (session->lcl_port); + /* *INDENT-ON* */ + } + } + clib_spinlock_unlock (&vcm->sessions_lockp); done: return rv; @@ -2548,9 +2855,9 @@ vppcom_session_accept (uint32_t listen_session_index, vppcom_endpt_t * ep, ssvm_lock_non_recursive (sh, 1); oldheap = ssvm_push_heap (sh); event_q = client_session->vpp_event_queue = - unix_shared_memory_queue_init (vcm->cfg.event_queue_size, - sizeof (session_fifo_event_t), - getpid (), 0 /* signal not sent */ ); + svm_queue_init (vcm->cfg.event_queue_size, + sizeof (session_fifo_event_t), + getpid (), 0 /* signal not sent */ ); ssvm_pop_heap (oldheap); ssvm_unlock_non_recursive (sh); } @@ -2580,6 +2887,57 @@ vppcom_session_accept (uint32_t listen_session_index, vppcom_endpt_t * ep, client_session->lcl_addr.is_ip4, clib_net_to_host_u16 (client_session->lcl_port)); + if (VPPCOM_DEBUG > 0) + { + client_session->elog_track.name = + (char *) format (0, "C:%d:S:%d%c", vcm->my_client_index, + client_session_index, 0); + elog_track_register (&vcm->elog_main, &client_session->elog_track); + + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "accept cut-thru: listen_handle:%x from_handle:%x", + .format_args = "i8i8", + }; + + struct + { + u64 handle[2]; + } *ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, client_session->elog_track); + ed->handle[0] = listen_vpp_handle; + ed->handle[1] = client_session->vpp_handle; + /* *INDENT-ON* */ + + if (client_session->lcl_addr.is_ip4) + { + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e2) = + { + .format = "accept cut-thru: S:%d %d.%d.%d.%d:%d ", + .format_args = "i4i1i1i1i1i2", + }; + + CLIB_PACKED (struct { + u32 session; + u8 addr[4]; + u16 port; + }) * ed2; + + ed2 = + ELOG_TRACK_DATA (&vcm->elog_main, e2, client_session->elog_track); + ed2->session = client_session_index; + ed2->addr[0] = client_session->lcl_addr.ip46.ip4.as_u8[0]; + ed2->addr[1] = client_session->lcl_addr.ip46.ip4.as_u8[1]; + ed2->addr[2] = client_session->lcl_addr.ip46.ip4.as_u8[2]; + ed2->addr[3] = client_session->lcl_addr.ip46.ip4.as_u8[3]; + ed2->port = clib_net_to_host_u16 (client_session->lcl_port); + /* *INDENT-ON* */ + } + } + clib_spinlock_unlock (&vcm->sessions_lockp); rv = (int) client_session_index; done: @@ -2881,7 +3239,7 @@ vppcom_session_read_ready (session_t * session, u32 session_index) session_fifo_event_t e; for (i = 0; i < n_to_dequeue; i++) - unix_shared_memory_queue_sub_raw (vcm->app_event_queue, (u8 *) & e); + svm_queue_sub_raw (vcm->app_event_queue, (u8 *) & e); pthread_mutex_unlock (&vcm->app_event_queue->mutex); } @@ -2895,7 +3253,7 @@ vppcom_session_write (uint32_t session_index, void *buf, int n) { session_t *session = 0; svm_fifo_t *tx_fifo; - unix_shared_memory_queue_t *q; + svm_queue_t *q; session_fifo_event_t evt; int rv, n_write; char *fifo_str; @@ -2961,8 +3319,7 @@ vppcom_session_write (uint32_t session_index, void *buf, int n) VCL_LOCK_AND_GET_SESSION (session_index, &session); q = session->vpp_event_queue; ASSERT (q); - unix_shared_memory_queue_add (q, (u8 *) & evt, - 0 /* do wait for mutex */ ); + svm_queue_add (q, (u8 *) & evt, 0 /* do wait for mutex */ ); clib_spinlock_unlock (&vcm->sessions_lockp); if (VPPCOM_DEBUG > 1) clib_warning ("[%d] vpp handle 0x%llx, sid %u: " @@ -3354,6 +3711,30 @@ vppcom_epoll_create (void) clib_warning ("[%d] Created vep_idx %u / sid %u!", getpid (), vep_idx, vep_idx); + if (VPPCOM_DEBUG > 0) + { + vep_session->elog_track.name = + (char *) format (0, "C:%d:VEP:%d%c", vcm->my_client_index, + vep_idx, 0); + elog_track_register (&vcm->elog_main, &vep_session->elog_track); + + /* *INDENT-OFF* */ + ELOG_TYPE_DECLARE (e) = + { + .format = "created epoll session:%d", + .format_args = "i4", + }; + + struct + { + u32 data; + } *ed; + + ed = ELOG_TRACK_DATA (&vcm->elog_main, e, vep_session->elog_track); + ed->data = vep_idx; + /* *INDENT-ON* */ + } + return (vep_idx); }