X-Git-Url: https://gerrit.fd.io/r/gitweb?a=blobdiff_plain;f=src%2Fvcl%2Fvppcom.c;h=dcf63d07063257b824045e864558366a0d0eb5d9;hb=8aa9aaff8e1fcf9e116e33e818b45998da71c363;hp=f05b03143e74f5bf13b684ca34ede557fb70c9f4;hpb=badeb95bcbb1352d4e5ab97e6524a5ef6f743240;p=vpp.git diff --git a/src/vcl/vppcom.c b/src/vcl/vppcom.c index f05b03143e7..dcf63d07063 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 @@ -127,11 +128,13 @@ typedef struct u8 proto; u64 client_queue_address; u64 options[16]; + elog_track_t elog_track; } session_t; typedef struct vppcom_cfg_t_ { u64 heapsize; + u32 vpp_api_q_length; u64 segment_baseva; u32 segment_size; u32 add_segment_size; @@ -149,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_ @@ -190,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; @@ -354,26 +363,77 @@ 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..."); - if (vl_client_connect_to_vlib ("/vpe-api", app_name, 32) < 0) + if (vl_client_connect_to_vlib ("/vpe-api", 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->app_state = STATE_APP_CONN_VPP; - return VPPCOM_OK; + 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); + + 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; + } + + return rv; } static u8 * @@ -507,8 +567,9 @@ vppcom_app_session_enable (void) if (PREDICT_FALSE (rv)) { if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] Session enable timed out, rv = %s (%d)", - getpid (), vppcom_retval_str (rv), rv); + clib_warning ("[%d] application session enable timed out! " + "returning %d (%s)", + getpid (), rv, vppcom_retval_str (rv)); return rv; } } @@ -550,10 +611,13 @@ vppcom_app_send_attach (void) bmp->options[APP_OPTIONS_PROXY_TRANSPORT] = (vcm->cfg.app_proxy_transport_tcp ? 1 << TRANSPORT_PROTO_TCP : 0) | (vcm->cfg.app_proxy_transport_udp ? 1 << TRANSPORT_PROTO_UDP : 0); - bmp->options[SESSION_OPTIONS_SEGMENT_SIZE] = vcm->cfg.segment_size; - bmp->options[SESSION_OPTIONS_ADD_SEGMENT_SIZE] = vcm->cfg.add_segment_size; - bmp->options[SESSION_OPTIONS_RX_FIFO_SIZE] = vcm->cfg.rx_fifo_size; - bmp->options[SESSION_OPTIONS_TX_FIFO_SIZE] = vcm->cfg.tx_fifo_size; + bmp->options[APP_OPTIONS_SEGMENT_SIZE] = vcm->cfg.segment_size; + bmp->options[APP_OPTIONS_ADD_SEGMENT_SIZE] = vcm->cfg.add_segment_size; + bmp->options[APP_OPTIONS_RX_FIFO_SIZE] = vcm->cfg.rx_fifo_size; + bmp->options[APP_OPTIONS_TX_FIFO_SIZE] = vcm->cfg.tx_fifo_size; + bmp->options[APP_OPTIONS_PREALLOC_FIFO_PAIRS] = + vcm->cfg.preallocated_fifo_pairs; + bmp->options[APP_OPTIONS_EVT_QUEUE_SIZE] = vcm->cfg.event_queue_size; if (nsid_len) { bmp->namespace_id_len = nsid_len; @@ -573,8 +637,8 @@ vppcom_app_attach (void) if (PREDICT_FALSE (rv)) { if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] application attach timed out, rv = %s (%d)", - getpid (), vppcom_retval_str (rv), rv); + clib_warning ("[%d] application attach timed out! returning %d (%s)", + getpid (), rv, vppcom_retval_str (rv)); return rv; } return VPPCOM_OK; @@ -699,7 +763,7 @@ vl_api_disconnect_session_t_handler (vl_api_disconnect_session_t * mp) if (VPPCOM_DEBUG > 1) clib_warning ("[%d] vpp handle 0x%llx, sid %u: " - "setting state to %d (%s)", + "setting state to 0x%x (%s)", getpid (), mp->handle, session_index, session->state, vppcom_session_state_str (session->state)); clib_spinlock_unlock (&vcm->sessions_lockp); @@ -733,9 +797,10 @@ vl_api_reset_session_t_handler (vl_api_reset_session_t * mp) if (PREDICT_FALSE (rval)) { rv = VNET_API_ERROR_INVALID_VALUE_2; - clib_warning ("[%d] ERROR: sid %u: session lookup failed! " - "returning %d %U", - getpid (), p[0], rv, format_api_error, rv); + clib_warning ("[%d] ERROR: vpp handle 0x%llx, sid %u: " + "session lookup failed! returning %d %U", + getpid (), mp->handle, p[0], + rv, format_api_error, rv); } else { @@ -771,34 +836,37 @@ vl_api_reset_session_t_handler (vl_api_reset_session_t * mp) static void vl_api_connect_session_reply_t_handler (vl_api_connect_session_reply_t * mp) { - session_t *session; + session_t *session = 0; u32 session_index; svm_fifo_t *rx_fifo, *tx_fifo; u8 is_cut_thru = 0; int rv; session_index = mp->context; + VCL_LOCK_AND_GET_SESSION (session_index, &session); +done: if (mp->retval) { - clib_warning ("[%d] ERROR: sid %u: connect failed! %U", - getpid (), session_index, format_api_error, - ntohl (mp->retval)); - return; + clib_warning ("[%d] ERROR: vpp handle 0x%llx, sid %u: " + "connect failed! %U", + getpid (), mp->handle, session_index, + format_api_error, ntohl (mp->retval)); + if (rv == VPPCOM_OK) + { + session->state = STATE_FAILED; + session->vpp_handle = mp->handle; + } + else + { + clib_warning ("[%s] ERROR: vpp handle 0x%llx, sid %u: " + "Invalid session index (%u)!", + getpid (), mp->handle, session_index); + } + goto done_unlock; } - if (VPPCOM_DEBUG > 1) - clib_warning ("[%d] sid %u: got a connect reply!", - getpid (), session_index); - - clib_spinlock_lock (&vcm->sessions_lockp); - if (pool_is_free_index (vcm->sessions, session_index)) - { - clib_spinlock_unlock (&vcm->sessions_lockp); - if (VPPCOM_DEBUG > 1) - clib_warning ("[%d] sid %d: session lookup failed!", - getpid (), session_index); - return; - } + if (rv) + goto done_unlock; /* We've been redirected */ if (mp->segment_name_length > 0) @@ -817,17 +885,15 @@ vl_api_connect_session_reply_t_handler (vl_api_connect_session_reply_t * mp) vec_reset_length (a->new_segment_indices); if (PREDICT_FALSE (rv)) { - clib_spinlock_unlock (&vcm->sessions_lockp); clib_warning ("[%d] sm_fifo_segment_attach ('%s') failed", getpid (), a->segment_name); - return; + goto done_unlock; } } /* * Setup session */ - session = pool_elt_at_index (vcm->sessions, session_index); session->is_cut_thru = is_cut_thru; session->vpp_event_queue = uword_to_pointer (mp->vpp_event_queue_address, unix_shared_memory_queue_t *); @@ -850,14 +916,14 @@ vl_api_connect_session_reply_t_handler (vl_api_connect_session_reply_t * mp) hash_set (vcm->session_index_by_vpp_handles, mp->handle, session_index); if (VPPCOM_DEBUG > 1) - clib_warning ("[%d] client sid %d, vpp handle 0x%llx\n" - " session_rx_fifo %p, refcnt %d\n" - " session_tx_fifo %p, refcnt %d", - getpid (), session_index, mp->handle, + clib_warning ("[%d] vpp handle 0x%llx, sid %u: connect succeeded!" + " session_rx_fifo %p, refcnt %d," + " session_tx_fifo %p, refcnt %d", + getpid (), mp->handle, session_index, session->server_rx_fifo, session->server_rx_fifo->refcnt, session->server_tx_fifo, session->server_tx_fifo->refcnt); - +done_unlock: clib_spinlock_unlock (&vcm->sessions_lockp); } @@ -926,34 +992,41 @@ vl_api_bind_sock_reply_t_handler (vl_api_bind_sock_reply_t * mp) u32 session_index = mp->context; int rv; + VCL_LOCK_AND_GET_SESSION (session_index, &session); +done: if (mp->retval) { - clib_warning ("[%d] ERROR: sid %u: bind failed: %U", - getpid (), session_index, format_api_error, + clib_warning ("[%d] ERROR: vpp handle 0x%llx, sid %u: bind failed: %U", + getpid (), mp->handle, session_index, format_api_error, ntohl (mp->retval)); rv = vppcom_session_at_index (session_index, &session); if (rv == VPPCOM_OK) - session->state = STATE_FAILED; - return; + { + session->state = STATE_FAILED; + session->vpp_handle = mp->handle; + } + else + { + clib_warning ("[%s] ERROR: vpp handle 0x%llx, sid %u: " + "Invalid session index (%u)!", + getpid (), mp->handle, session_index); + } + goto done_unlock; } - clib_spinlock_lock (&vcm->sessions_lockp); - rv = vppcom_session_at_index (session_index, &session); - if (rv == VPPCOM_OK) - { - session->vpp_handle = mp->handle; - session->lcl_addr.is_ip4 = mp->lcl_is_ip4; - clib_memcpy (&session->lcl_addr.ip46, mp->lcl_ip, - sizeof (session->peer_addr.ip46)); - session->lcl_port = mp->lcl_port; - vppcom_session_table_add_listener (mp->handle, session_index); - session->is_listen = 1; - session->state = STATE_LISTEN; + session->vpp_handle = mp->handle; + session->lcl_addr.is_ip4 = mp->lcl_is_ip4; + clib_memcpy (&session->lcl_addr.ip46, mp->lcl_ip, + sizeof (session->peer_addr.ip46)); + session->lcl_port = mp->lcl_port; + vppcom_session_table_add_listener (mp->handle, session_index); + session->is_listen = 1; + session->state = STATE_LISTEN; - if (VPPCOM_DEBUG > 1) - clib_warning ("[%d] sid %u: bind succeeded! ", getpid (), - mp->context); - } + if (VPPCOM_DEBUG > 1) + clib_warning ("[%d] vpp handle 0x%llx, sid %u: bind succeeded!", + getpid (), mp->handle, mp->context); +done_unlock: clib_spinlock_unlock (&vcm->sessions_lockp); } @@ -1053,7 +1126,7 @@ format_ip46_address (u8 * s, va_list * args) } static inline void -vppcom_send_accept_session_reply (u32 handle, int retval) +vppcom_send_accept_session_reply (u64 handle, u32 context, int retval) { vl_api_accept_session_reply_t *rmp; @@ -1061,6 +1134,7 @@ vppcom_send_accept_session_reply (u32 handle, int retval) memset (rmp, 0, sizeof (*rmp)); rmp->_vl_msg_id = ntohs (VL_API_ACCEPT_SESSION_REPLY); rmp->retval = htonl (retval); + rmp->context = context; rmp->handle = handle; vl_msg_api_send_shmem (vcm->vl_input_queue, (u8 *) & rmp); } @@ -1076,7 +1150,7 @@ vl_api_accept_session_t_handler (vl_api_accept_session_t * mp) if (!clib_fifo_free_elts (vcm->client_session_index_fifo)) { clib_warning ("[%d] client session queue is full!", getpid ()); - vppcom_send_accept_session_reply (mp->handle, + vppcom_send_accept_session_reply (mp->handle, mp->context, VNET_API_ERROR_QUEUE_FULL); clib_spinlock_unlock (&vcm->sessions_lockp); return; @@ -1102,6 +1176,7 @@ vl_api_accept_session_t_handler (vl_api_accept_session_t * mp) tx_fifo->client_session_index = session_index; session->vpp_handle = mp->handle; + session->client_context = mp->context; session->server_rx_fifo = rx_fifo; session->server_tx_fifo = tx_fifo; session->vpp_event_queue = uword_to_pointer (mp->vpp_event_queue_address, @@ -1125,17 +1200,16 @@ vl_api_accept_session_t_handler (vl_api_accept_session_t * mp) clib_spinlock_unlock (&vcm->sessions_lockp); if (VPPCOM_DEBUG > 1) - { - u8 *ip_str = format (0, "%U", format_ip46_address, &mp->ip, mp->is_ip4); - clib_warning ("[%d] received request to accept session (sid %d) " - "from %s:%d", getpid (), session_index, ip_str, - clib_net_to_host_u16 (mp->port)); - vec_free (ip_str); - } + clib_warning ("[%d] vpp handle 0x%llx, sid %u: client accept " + "request from %s address %U port %d queue %p!", getpid (), + 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); } static void -vppcom_send_connect_session_reply (session_t * session, int retval) +vppcom_send_connect_session_reply (session_t * session, u32 session_index, + u64 vpp_handle, u32 context, int retval) { vl_api_connect_session_reply_t *rmp; u32 len; @@ -1143,8 +1217,17 @@ vppcom_send_connect_session_reply (session_t * session, int retval) rmp = vl_msg_api_alloc (sizeof (*rmp)); memset (rmp, 0, sizeof (*rmp)); - rmp->_vl_msg_id = ntohs (VL_API_CONNECT_SESSION_REPLY); + + if (!session) + { + rmp->context = context; + rmp->handle = vpp_handle; + rmp->retval = htonl (retval); + vl_msg_api_send_shmem (vcm->vl_input_queue, (u8 *) & rmp); + return; + } + rmp->context = session->client_context; rmp->retval = htonl (retval); rmp->handle = session->vpp_handle; @@ -1183,8 +1266,10 @@ vl_api_connect_sock_t_handler (vl_api_connect_sock_t * mp) if (VPPCOM_DEBUG > 1) clib_warning ("[%d] client session queue is full!", getpid ()); - /* TBD: fix handle missing in api msg. */ - vppcom_send_accept_session_reply (0, VNET_API_ERROR_QUEUE_FULL); + /* TBD: Fix api to include vpp handle */ + vppcom_send_connect_session_reply (0 /* session */ , 0 /* sid */ , + 0 /* handle */ , mp->context, + VNET_API_ERROR_QUEUE_FULL); return; } @@ -1310,8 +1395,9 @@ vppcom_session_disconnect (u32 session_index) if (PREDICT_FALSE (is_listen)) { - clib_warning ("[%d] ERROR: sid %u: Cannot disconnect a " - "listen socket!", getpid (), session_index); + clib_warning ("[%d] ERROR: vpp handle 0x%llx, sid %u: " + "Cannot disconnect a listen socket!", + getpid (), vpp_handle, session_index); rv = VPPCOM_EBADFD; goto done; } @@ -1328,8 +1414,9 @@ vppcom_session_disconnect (u32 session_index) vppcom_send_disconnect_session_reply (vpp_handle, session_index, 0 /* rv */ ); if (VPPCOM_DEBUG > 1) - clib_warning ("[%d] sid %u: sending disconnect REPLY...", - getpid (), session_index); + clib_warning ("[%d] vpp handle 0x%llx, sid %u: " + "sending disconnect REPLY...", + getpid (), vpp_handle, session_index); } /* Otherwise, send a disconnect session msg... @@ -1337,9 +1424,9 @@ vppcom_session_disconnect (u32 session_index) else { if (VPPCOM_DEBUG > 1) - clib_warning ("[%d] sid %u: sending disconnect...", - getpid (), session_index, state, - vppcom_session_state_str (state)); + clib_warning ("[%d] vpp handle 0x%llx, sid %u: " + "sending disconnect...", + getpid (), vpp_handle, session_index); vppcom_send_disconnect_session (vpp_handle, session_index); } @@ -1361,9 +1448,9 @@ vppcom_session_disconnect (u32 session_index) if (VPPCOM_DEBUG > 1) clib_warning ("[%d] sid %d: freeing cut-thru fifos in " - "sm_seg_index %d\n" - " server_rx_fifo %p, refcnt = %d\n" - " server_tx_fifo %p, refcnt = %d", + "sm_seg_index %d! " + " server_rx_fifo %p, refcnt = %d" + " server_tx_fifo %p, refcnt = %d", getpid (), session_index, session->sm_seg_index, session->server_rx_fifo, session->server_rx_fifo->refcnt, @@ -1425,6 +1512,7 @@ vppcom_cfg_init (vppcom_cfg_t * vcl_cfg) ASSERT (vcl_cfg); vcl_cfg->heapsize = (256ULL << 20); + vcl_cfg->vpp_api_q_length = 1024; vcl_cfg->segment_baseva = 0x200000000ULL; vcl_cfg->segment_size = (256 << 20); vcl_cfg->add_segment_size = (128 << 20); @@ -1436,6 +1524,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 @@ -1587,7 +1677,7 @@ vppcom_cfg_read (char *conf_fname) u8 vc_cfg_input = 0; u8 *chroot_path; struct stat s; - u32 uid, gid; + u32 uid, gid, q_len; fd = open (conf_fname, O_RDONLY); if (fd < 0) @@ -1646,6 +1736,23 @@ vppcom_cfg_read (char *conf_fname) getpid (), chroot_path); chroot_path = 0; /* Don't vec_free() it! */ } + else if (unformat (line_input, "vpp-api-q-length %d", &q_len)) + { + if (q_len < vcl_cfg->vpp_api_q_length) + { + clib_warning ("[%d] ERROR: configured vpp-api-q-length " + "(%u) is too small! Using default: %u ", + getpid (), q_len, vcl_cfg->vpp_api_q_length); + } + else + { + vcl_cfg->vpp_api_q_length = q_len; + + if (VPPCOM_DEBUG > 0) + clib_warning ("[%d] configured vpp-api-q-length %u", + getpid (), vcl_cfg->vpp_api_q_length); + } + } else if (unformat (line_input, "uid %d", &uid)) { vl_set_memory_uid (uid); @@ -2057,14 +2164,32 @@ 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) + { + 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; + } + vppcom_app_detach (); rv = vppcom_wait_for_app_state_change (STATE_APP_ENABLED); if (PREDICT_FALSE (rv)) { if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] application detach timed out, rv = %s (%d)", - getpid (), vppcom_retval_str (rv), rv); + 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; @@ -2104,6 +2229,7 @@ vppcom_session_close (uint32_t session_index) u8 is_vep_session; u32 next_sid; u32 vep_idx; + u64 vpp_handle; uword *p; session_state_t state; @@ -2114,20 +2240,28 @@ vppcom_session_close (uint32_t session_index) next_sid = session->vep.next_sid; vep_idx = session->vep.vep_idx; state = session->state; + vpp_handle = session->vpp_handle; clib_spinlock_unlock (&vcm->sessions_lockp); if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] sid %d: closing session...", getpid (), - session_index); + { + if (is_vep) + clib_warning ("[%d] vep_idx %u / sid %u: closing epoll session...", + getpid (), session_index, session_index); + else + clib_warning ("[%d] vpp handle 0x%llx, sid %d: closing session...", + getpid (), vpp_handle, session_index); + } if (is_vep) { while (next_sid != ~0) { rv = vppcom_epoll_ctl (session_index, EPOLL_CTL_DEL, next_sid, 0); - if ((VPPCOM_DEBUG > 0) && (rv < 0)) - clib_warning ("[%d] sid %u: EPOLL_CTL_DEL vep_idx %u failed, " - "rv = %d (%s)", getpid (), next_sid, vep_idx, + if ((VPPCOM_DEBUG > 0) && PREDICT_FALSE (rv < 0)) + clib_warning ("[%d] vpp handle 0x%llx, sid %u: EPOLL_CTL_DEL " + "vep_idx %u failed! rv %d (%s)", getpid (), + vpp_handle, next_sid, vep_idx, rv, vppcom_retval_str (rv)); VCL_LOCK_AND_GET_SESSION (session_index, &session); @@ -2141,9 +2275,10 @@ vppcom_session_close (uint32_t session_index) { rv = vppcom_epoll_ctl (vep_idx, EPOLL_CTL_DEL, session_index, 0); if ((VPPCOM_DEBUG > 0) && (rv < 0)) - clib_warning ("[%d] sid %u: EPOLL_CTL_DEL vep_idx %u failed! " - "rv = %d (%s)", getpid (), session_index, vep_idx, - rv, vppcom_retval_str (rv)); + clib_warning ("[%d] vpp handle 0x%llx, sid %u: EPOLL_CTL_DEL " + "vep_idx %u failed! rv %d (%s)", + getpid (), vpp_handle, session_index, + vep_idx, rv, vppcom_retval_str (rv)); } if (is_listen) @@ -2154,10 +2289,10 @@ vppcom_session_close (uint32_t session_index) if (PREDICT_FALSE (rv < 0)) { if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] sid %u: listener unbind failed! " - "rv = %d (%s)", - getpid (), session_index, rv, - vppcom_retval_str (rv)); + clib_warning ("[%d] vpp handle 0x%llx, sid %u: " + "listener unbind failed! rv %d (%s)", + getpid (), vpp_handle, session_index, + rv, vppcom_retval_str (rv)); } } } @@ -2166,26 +2301,33 @@ vppcom_session_close (uint32_t session_index) { rv = vppcom_session_disconnect (session_index); if (PREDICT_FALSE (rv < 0)) - clib_warning ("[%d] ERROR: sid %u: session disconnect failed! " - "rv %d (%s)", getpid (), session_index, rv, - vppcom_retval_str (rv)); + clib_warning ("[%d] ERROR: vpp handle 0x%llx, sid %u: " + "session disconnect failed! rv %d (%s)", + getpid (), vpp_handle, session_index, + rv, vppcom_retval_str (rv)); } } VCL_LOCK_AND_GET_SESSION (session_index, &session); - - if (session->vpp_handle != ~0) + vpp_handle = session->vpp_handle; + if (vpp_handle != ~0) { - p = hash_get (vcm->session_index_by_vpp_handles, session->vpp_handle); + p = hash_get (vcm->session_index_by_vpp_handles, vpp_handle); if (p) - hash_unset (vcm->session_index_by_vpp_handles, session->vpp_handle); + hash_unset (vcm->session_index_by_vpp_handles, vpp_handle); } pool_put_index (vcm->sessions, session_index); clib_spinlock_unlock (&vcm->sessions_lockp); if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] sid %u: session removed.", getpid (), session_index); - + { + if (is_vep) + clib_warning ("[%d] vep_idx %u / sid %u: epoll session removed.", + getpid (), session_index, session_index); + else + clib_warning ("[%d] vpp handle 0x%llx, sid %u: session removed.", + getpid (), vpp_handle, session_index); + } done: return rv; } @@ -2216,10 +2358,11 @@ vppcom_session_bind (uint32_t session_index, vppcom_endpt_t * ep) session->lcl_port = ep->port; if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] sid %u: bound to local address %U " - "port %u, proto %s", - getpid (), session_index, format_ip46_address, - &session->lcl_addr.ip46, session->lcl_addr.is_ip4, + clib_warning ("[%d] sid %u: binding to local %s address %U " + "port %u, proto %s", getpid (), session_index, + session->lcl_addr.is_ip4 ? "IPv4" : "IPv6", + format_ip46_address, &session->lcl_addr.ip46, + session->lcl_addr.is_ip4, clib_net_to_host_u16 (session->lcl_port), session->proto ? "UDP" : "TCP"); @@ -2232,7 +2375,8 @@ int vppcom_session_listen (uint32_t listen_session_index, uint32_t q_len) { session_t *listen_session = 0; - int rv; + u64 listen_vpp_handle; + int rv, retval; VCL_LOCK_AND_GET_SESSION (listen_session_index, &listen_session); @@ -2245,34 +2389,41 @@ vppcom_session_listen (uint32_t listen_session_index, uint32_t q_len) goto done; } + listen_vpp_handle = listen_session->vpp_handle; if (listen_session->is_listen) { clib_spinlock_unlock (&vcm->sessions_lockp); if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] sid %u: already in listen state!", - getpid (), listen_session_index); + clib_warning ("[%d] vpp handle 0x%llx, sid %u: " + "already in listen state!", + getpid (), listen_vpp_handle, listen_session_index); rv = VPPCOM_OK; goto done; } if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] sid %u: sending bind request...", - getpid (), listen_session_index); + clib_warning ("[%d] vpp handle 0x%llx, sid %u: sending bind request...", + getpid (), listen_vpp_handle, listen_session_index); vppcom_send_bind_sock (listen_session, listen_session_index); clib_spinlock_unlock (&vcm->sessions_lockp); - rv = + retval = vppcom_wait_for_session_state_change (listen_session_index, STATE_LISTEN, vcm->cfg.session_timeout); - if (PREDICT_FALSE (rv)) + + VCL_LOCK_AND_GET_SESSION (listen_session_index, &listen_session); + if (PREDICT_FALSE (retval)) { if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] sid %u: bind failed! returning %d (%d)", - getpid (), vppcom_retval_str (rv), rv); - return rv; + clib_warning ("[%d] vpp handle 0x%llx, sid %u: bind failed! " + "returning %d (%s)", getpid (), + listen_session->vpp_handle, listen_session_index, + retval, vppcom_retval_str (retval)); + clib_spinlock_unlock (&vcm->sessions_lockp); + rv = retval; + goto done; } - VCL_LOCK_AND_GET_SESSION (listen_session_index, &listen_session); clib_fifo_validate (vcm->client_session_index_fifo, q_len); clib_spinlock_unlock (&vcm->sessions_lockp); done: @@ -2289,6 +2440,7 @@ vppcom_session_accept (uint32_t listen_session_index, vppcom_endpt_t * ep, int rv; f64 wait_for; char *cut_thru_str; + u64 listen_vpp_handle; VCL_LOCK_AND_GET_SESSION (listen_session_index, &listen_session); @@ -2301,12 +2453,15 @@ vppcom_session_accept (uint32_t listen_session_index, vppcom_endpt_t * ep, goto done; } + listen_vpp_handle = listen_session->vpp_handle; if (listen_session->state != STATE_LISTEN) { - clib_spinlock_unlock (&vcm->sessions_lockp); - clib_warning ("[%d] ERROR: sid %u: not in listen state! " - "state 0x%x (%s)", getpid (), listen_session->state, + clib_warning ("[%d] ERROR: vpp handle 0x%llx, sid %u: " + "not in listen state! state 0x%x (%s)", getpid (), + listen_vpp_handle, listen_session_index, + listen_session->state, vppcom_session_state_str (listen_session->state)); + clib_spinlock_unlock (&vcm->sessions_lockp); rv = VPPCOM_EBADFD; goto done; } @@ -2321,9 +2476,9 @@ vppcom_session_accept (uint32_t listen_session_index, vppcom_endpt_t * ep, if (rv) { if ((VPPCOM_DEBUG > 0)) - clib_warning ("[%d] sid %u: accept failed! " - "returning = %d (%s)", - getpid (), listen_session_index, + clib_warning ("[%d] vpp handle 0x%llx, sid %u: accept failed! " + "returning %d (%s)", getpid (), + listen_vpp_handle, listen_session_index, rv, vppcom_retval_str (rv)); if ((wait_for == 0) || (wait_for_time > 0)) goto done; @@ -2335,12 +2490,22 @@ vppcom_session_accept (uint32_t listen_session_index, vppcom_endpt_t * ep, clib_spinlock_lock (&vcm->sessions_lockp); clib_fifo_sub1 (vcm->client_session_index_fifo, client_session_index); rv = vppcom_session_at_index (client_session_index, &client_session); - ASSERT (rv == VPPCOM_OK); + if (PREDICT_FALSE (rv)) + { + rv = VPPCOM_ECONNABORTED; + clib_warning ("[%d] vpp handle 0x%llx, sid %u: client sid %u " + "lookup failed! returning %d (%s)", getpid (), + listen_vpp_handle, listen_session_index, + client_session_index, rv, vppcom_retval_str (rv)); + goto done; + } client_session->is_nonblocking = (flags & O_NONBLOCK) ? 1 : 0; if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] sid %u: Got a client request! flags %d, " - "is_nonblocking %u", getpid (), client_session_index, + clib_warning ("[%d] vpp handle 0x%llx, sid %u: Got a client request! " + "vpp handle 0x%llx, sid %u, flags %d, is_nonblocking %u", + getpid (), listen_vpp_handle, listen_session_index, + client_session->vpp_handle, client_session_index, flags, client_session->is_nonblocking); ep->vrf = client_session->vrf; @@ -2375,12 +2540,18 @@ vppcom_session_accept (uint32_t listen_session_index, vppcom_endpt_t * ep, rv = svm_fifo_segment_create (a); if (PREDICT_FALSE (rv)) { - clib_warning ("[%d] ERROR: sid %u: " - "svm_fifo_segment_create ('%s') failed! rv %d", - getpid (), client_session_index, a->segment_name, rv); + clib_warning ("[%d] ERROR: vpp handle 0x%llx, sid %u: " + "client sid %u svm_fifo_segment_create ('%s') " + "failed! rv %d", getpid (), listen_vpp_handle, + listen_session_index, client_session_index, + a->segment_name, rv); vec_reset_length (a->new_segment_indices); rv = VNET_API_ERROR_URI_FIFO_CREATE_FAILED; - vppcom_send_connect_session_reply (client_session, rv); + vppcom_send_connect_session_reply (client_session, + client_session_index, + client_session->vpp_handle, + client_session->client_context, + rv); clib_spinlock_unlock (&vcm->sessions_lockp); rv = VPPCOM_ENOMEM; goto done; @@ -2397,12 +2568,17 @@ vppcom_session_accept (uint32_t listen_session_index, vppcom_endpt_t * ep, if (PREDICT_FALSE (!client_session->server_rx_fifo)) { svm_fifo_segment_delete (seg); - clib_warning ("[%d] ERROR: sid %u: rx fifo alloc failed! " - "size %ld (0x%lx)", getpid (), - client_session_index, + clib_warning ("[%d] ERROR: vpp handle 0x%llx, sid %u: " + "client sid %u rx fifo alloc failed! " + "size %ld (0x%lx)", getpid (), listen_vpp_handle, + listen_session_index, client_session_index, vcm->cfg.rx_fifo_size, vcm->cfg.rx_fifo_size); rv = VNET_API_ERROR_URI_FIFO_CREATE_FAILED; - vppcom_send_connect_session_reply (client_session, rv); + vppcom_send_connect_session_reply (client_session, + client_session_index, + client_session->vpp_handle, + client_session->client_context, + rv); clib_spinlock_unlock (&vcm->sessions_lockp); rv = VPPCOM_ENOMEM; goto done; @@ -2416,12 +2592,17 @@ vppcom_session_accept (uint32_t listen_session_index, vppcom_endpt_t * ep, if (PREDICT_FALSE (!client_session->server_tx_fifo)) { svm_fifo_segment_delete (seg); - clib_warning ("[%d] ERROR: sid %u: tx fifo alloc failed! " - "size %ld (0x%lx)", - getpid (), client_session_index, + clib_warning ("[%d] ERROR: vpp handle 0x%llx, sid %u: " + "client sid %u tx fifo alloc failed! " + "size %ld (0x%lx)", getpid (), listen_vpp_handle, + listen_session_index, client_session_index, vcm->cfg.tx_fifo_size, vcm->cfg.tx_fifo_size); rv = VNET_API_ERROR_URI_FIFO_CREATE_FAILED; - vppcom_send_connect_session_reply (client_session, rv); + vppcom_send_connect_session_reply (client_session, + client_session_index, + client_session->vpp_handle, + client_session->client_context, + rv); clib_spinlock_unlock (&vcm->sessions_lockp); rv = VPPCOM_ENOMEM; goto done; @@ -2430,10 +2611,10 @@ vppcom_session_accept (uint32_t listen_session_index, vppcom_endpt_t * ep, client_session_index; if (VPPCOM_DEBUG > 1) - clib_warning ("[%d] sid %u: created segment '%s', " - "rx_fifo %p, tx_fifo %p", - getpid (), client_session_index, - client_session->segment_name, + clib_warning ("[%d] vpp handle 0x%llx, sid %u: client sid %u " + "created segment '%s', rx_fifo %p, tx_fifo %p", + getpid (), listen_vpp_handle, listen_session_index, + client_session_index, client_session->segment_name, client_session->server_rx_fifo, client_session->server_tx_fifo); @@ -2452,18 +2633,26 @@ vppcom_session_accept (uint32_t listen_session_index, vppcom_endpt_t * ep, ssvm_unlock_non_recursive (sh); } #endif - vppcom_send_connect_session_reply (client_session, 0); + vppcom_send_connect_session_reply (client_session, + client_session_index, + client_session->vpp_handle, + client_session->client_context, + 0 /* retval OK */ ); } else { cut_thru_str = " "; - vppcom_send_accept_session_reply (client_session->vpp_handle, 0); + vppcom_send_accept_session_reply (client_session->vpp_handle, + client_session->client_context, + 0 /* retval OK */ ); } if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] sid %u: accepted%sconnection to local %s address " - "%U port %u", - getpid (), client_session_index, cut_thru_str, + clib_warning ("[%d] vpp handle 0x%llx, sid %u: accepted vpp handle " + "0x%llx, sid %u%sconnection to local %s address " + "%U port %u", getpid (), listen_vpp_handle, + listen_session_index, client_session->vpp_handle, + client_session_index, cut_thru_str, client_session->lcl_addr.is_ip4 ? "IPv4" : "IPv6", format_ip46_address, &client_session->lcl_addr.ip46, client_session->lcl_addr.is_ip4, @@ -2479,7 +2668,8 @@ int vppcom_session_connect (uint32_t session_index, vppcom_endpt_t * server_ep) { session_t *session = 0; - int rv; + int rv, retval = VPPCOM_OK; + u64 vpp_handle = ~0; VCL_LOCK_AND_GET_SESSION (session_index, &session); @@ -2492,11 +2682,13 @@ vppcom_session_connect (uint32_t session_index, vppcom_endpt_t * server_ep) goto done; } + vpp_handle = session->vpp_handle; if (PREDICT_FALSE (session->is_server)) { clib_spinlock_unlock (&vcm->sessions_lockp); - clib_warning ("[%d] ERROR: sid %u: is in use as a server session!", - getpid (), session_index); + clib_warning ("[%d] ERROR: vpp handle 0x%llx, sid %u: is in use " + "as a server session!", getpid (), vpp_handle, + session_index); rv = VPPCOM_EBADFD; goto done; } @@ -2504,9 +2696,9 @@ vppcom_session_connect (uint32_t session_index, vppcom_endpt_t * server_ep) if (PREDICT_FALSE (session->state & CLIENT_STATE_OPEN)) { if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] sid %u: session already connected to " - "%s %U port %d proto %s, state 0x%x (%s)", - getpid (), session_index, + clib_warning ("[%d] vpp handle 0x%llx, sid %u: session already " + "connected to %s %U port %d proto %s, state 0x%x (%s)", + getpid (), vpp_handle, session_index, session->peer_addr.is_ip4 ? "IPv4" : "IPv6", format_ip46_address, &session->peer_addr.ip46, session->peer_addr.is_ip4, @@ -2515,7 +2707,6 @@ vppcom_session_connect (uint32_t session_index, vppcom_endpt_t * server_ep) vppcom_session_state_str (session->state)); clib_spinlock_unlock (&vcm->sessions_lockp); - rv = VPPCOM_OK; goto done; } @@ -2525,8 +2716,9 @@ vppcom_session_connect (uint32_t session_index, vppcom_endpt_t * server_ep) session->peer_port = server_ep->port; if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] sid %u: connecting to server %s %U port %d proto %s", - getpid (), session_index, + clib_warning ("[%d] vpp handle 0x%llx, sid %u: connecting to server " + "%s %U port %d proto %s", + getpid (), vpp_handle, session_index, session->peer_addr.is_ip4 ? "IPv4" : "IPv6", format_ip46_address, &session->peer_addr.ip46, session->peer_addr.is_ip4, @@ -2536,18 +2728,27 @@ vppcom_session_connect (uint32_t session_index, vppcom_endpt_t * server_ep) vppcom_send_connect_sock (session, session_index); clib_spinlock_unlock (&vcm->sessions_lockp); - rv = vppcom_wait_for_session_state_change (session_index, STATE_CONNECT, - vcm->cfg.session_timeout); - if (PREDICT_FALSE (rv)) + retval = + vppcom_wait_for_session_state_change (session_index, STATE_CONNECT, + vcm->cfg.session_timeout); + + VCL_LOCK_AND_GET_SESSION (session_index, &session); + vpp_handle = session->vpp_handle; + clib_spinlock_unlock (&vcm->sessions_lockp); + +done: + if (PREDICT_FALSE (retval)) { + rv = retval; if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] sid %u: connect failed! returning %d (%s)", - getpid (), session_index, rv, vppcom_retval_str (rv)); + clib_warning ("[%d] vpp handle 0x%llx, sid %u: connect failed! " + "returning %d (%s)", getpid (), vpp_handle, + session_index, rv, vppcom_retval_str (rv)); } else if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] sid %d: connected!", getpid (), session_index); + clib_warning ("[%d] vpp handle 0x%llx, sid %u: connected!", + getpid (), vpp_handle, session_index); -done: return rv; } @@ -2564,6 +2765,7 @@ vppcom_session_read_internal (uint32_t session_index, void *buf, int n, session_state_t state; u8 is_server; u8 is_nonblocking; + u64 vpp_handle; ASSERT (buf); @@ -2578,6 +2780,7 @@ vppcom_session_read_internal (uint32_t session_index, void *buf, int n, goto done; } + vpp_handle = session->vpp_handle; is_server = session->is_server; is_nonblocking = session->is_nonblocking; state = session->state; @@ -2588,10 +2791,10 @@ vppcom_session_read_internal (uint32_t session_index, void *buf, int n, VPPCOM_ECONNRESET : VPPCOM_ENOTCONN); if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] sid %u: %s session is not open! " - "state 0x%x (%s), returning %d (%s)", - getpid (), session_index, is_server ? - "server" : "client", state, + clib_warning ("[%d] vpp handle 0x%llx, sid %u: %s session is " + "not open! state 0x%x (%s), returning %d (%s)", + getpid (), vpp_handle, session_index, + is_server ? "server" : "client", state, vppcom_session_state_str (state), rv, vppcom_retval_str (rv)); goto done; @@ -2628,10 +2831,10 @@ vppcom_session_read_internal (uint32_t session_index, void *buf, int n, if (VPPCOM_DEBUG > 1) { - clib_warning ("[%d] sid %u: Empty fifo with %s session " - "state 0x%x (%s)!\n" - " Setting state to %d (%s), returning %d (%s)", - getpid (), session_index, + clib_warning ("[%d] vpp handle 0x%llx, sid %u: Empty fifo " + "with %s session state 0x%x (%s)!" + " Setting state to 0x%x (%s), returning %d (%s)", + getpid (), vpp_handle, session_index, is_server ? "server" : "client", state, vppcom_session_state_str (state), new_state, vppcom_session_state_str (new_state), @@ -2651,11 +2854,13 @@ vppcom_session_read_internal (uint32_t session_index, void *buf, int n, if (VPPCOM_DEBUG > 2) { if (rv > 0) - clib_warning ("[%d] sid %u: read %d bytes from %s (%p)", getpid (), + clib_warning ("[%d] vpp handle 0x%llx, sid %u: read %d bytes " + "from %s (%p)", getpid (), vpp_handle, session_index, n_read, fifo_str, rx_fifo); else - clib_warning ("[%d] sid %u: nothing read, returning %d (%s)", - getpid (), session_index, rv, vppcom_retval_str (rv)); + clib_warning ("[%d] vpp handle 0x%llx, sid %u: nothing read! " + "returning %d (%s)", getpid (), vpp_handle, + session_index, rv, vppcom_retval_str (rv)); } done: return rv; @@ -2682,6 +2887,7 @@ vppcom_session_read_ready (session_t * session, u32 session_index) int rv; u8 is_server = session->is_server; session_state_t state = session->state; + u64 vpp_handle = session->vpp_handle; /* Assumes caller has acquired spinlock: vcm->sessions_lockp */ if (PREDICT_FALSE (session->is_vep)) @@ -2702,9 +2908,10 @@ vppcom_session_read_ready (session_t * session, u32 session_index) VPPCOM_ENOTCONN); if (VPPCOM_DEBUG > 1) - clib_warning ("[%d] sid %u: %s session is not open! " - "state 0x%x (%s), returning %d (%s)", getpid (), - session_index, is_server ? "server" : "client", + clib_warning ("[%d] vpp handle 0x%llx, sid %u: %s session is " + "not open! state 0x%x (%s), returning %d (%s)", + getpid (), vpp_handle, session_index, + is_server ? "server" : "client", state, vppcom_session_state_str (state), rv, vppcom_retval_str (rv)); goto done; @@ -2730,10 +2937,10 @@ vppcom_session_read_ready (session_t * session, u32 session_index) if (VPPCOM_DEBUG > 1) { - clib_warning ("[%d] sid %u: Empty fifo with %s session " - "state 0x%x (%s)!\n" - " Setting state to %d (%s), returning %d (%s)", - getpid (), session_index, + clib_warning ("[%d] vpp handle 0x%llx, sid %u: Empty fifo with" + " %s session state 0x%x (%s)! Setting state to " + "0x%x (%s), returning %d (%s)", + getpid (), session_index, vpp_handle, is_server ? "server" : "client", state, vppcom_session_state_str (state), new_state, vppcom_session_state_str (new_state), @@ -2744,6 +2951,19 @@ vppcom_session_read_ready (session_t * session, u32 session_index) } } rv = ready; + + if (vcm->app_event_queue->cursize && + !pthread_mutex_trylock (&vcm->app_event_queue->mutex)) + { + u32 i, n_to_dequeue = vcm->app_event_queue->cursize; + 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); + + pthread_mutex_unlock (&vcm->app_event_queue->mutex); + } + done: return rv; } @@ -2761,6 +2981,7 @@ vppcom_session_write (uint32_t session_index, void *buf, int n) u8 is_server; u8 is_nonblocking; session_state_t state; + u64 vpp_handle; ASSERT (buf); @@ -2769,8 +2990,9 @@ vppcom_session_write (uint32_t session_index, void *buf, int n) if (PREDICT_FALSE (session->is_vep)) { clib_spinlock_unlock (&vcm->sessions_lockp); - clib_warning ("[%d] ERROR: sid %u: cannot write to an epoll session!", - getpid (), session_index); + clib_warning ("[%d] ERROR: vpp handle 0x%llx, sid %u: " + "cannot write to an epoll session!", + getpid (), session->vpp_handle, session_index); rv = VPPCOM_EBADFD; goto done; @@ -2778,6 +3000,7 @@ vppcom_session_write (uint32_t session_index, void *buf, int n) is_server = session->is_server; is_nonblocking = session->is_nonblocking; + vpp_handle = session->vpp_handle; state = session->state; if (!(state & (SERVER_STATE_OPEN | CLIENT_STATE_OPEN))) { @@ -2786,9 +3009,10 @@ vppcom_session_write (uint32_t session_index, void *buf, int n) clib_spinlock_unlock (&vcm->sessions_lockp); if (VPPCOM_DEBUG > 1) - clib_warning ("[%d] sid %u: %s session is not open! state 0x%x (%s)", - getpid (), session_index, is_server ? - "server" : "client", state, + clib_warning ("[%d] vpp handle 0x%llx, sid %u: " + "%s session is not open! state 0x%x (%s)", + getpid (), vpp_handle, session_index, + is_server ? "server" : "client", state, vppcom_session_state_str (state)); goto done; } @@ -2819,9 +3043,10 @@ vppcom_session_write (uint32_t session_index, void *buf, int n) 0 /* do wait for mutex */ ); clib_spinlock_unlock (&vcm->sessions_lockp); if (VPPCOM_DEBUG > 1) - clib_warning ("[%d] sid %u: added FIFO_EVENT_APP_TX to " + clib_warning ("[%d] vpp handle 0x%llx, sid %u: " + "added FIFO_EVENT_APP_TX to " "vpp_event_q %p, n_write %d", getpid (), - session_index, q, n_write); + vpp_handle, session_index, q, n_write); } if (n_write <= 0) @@ -2840,10 +3065,10 @@ vppcom_session_write (uint32_t session_index, void *buf, int n) if (VPPCOM_DEBUG > 1) { - clib_warning ("[%d] sid %u: Empty fifo with %s session " - "state 0x%x (%s)!\n" - " Setting state to %d (%s), returning %d (%s)", - getpid (), session_index, + clib_warning ("[%d] vpp handle 0x%llx, sid %u: " + "Empty fifo with %s session state 0x%x (%s)!" + " Setting state to 0x%x (%s), returning %d (%s)", + getpid (), vpp_handle, session_index, is_server ? "server" : "client", state, vppcom_session_state_str (state), new_state, vppcom_session_state_str (new_state), @@ -2863,10 +3088,12 @@ vppcom_session_write (uint32_t session_index, void *buf, int n) if (VPPCOM_DEBUG > 2) { if (n_write <= 0) - clib_warning ("[%d] sid %u: FIFO-FULL %s (%p)", getpid (), + clib_warning ("[%d] vpp handle 0x%llx, sid %u: " + "FIFO-FULL %s (%p)", getpid (), vpp_handle, session_index, fifo_str, tx_fifo); else - clib_warning ("[%d] sid %u: wrote %d bytes to %s (%p)", getpid (), + clib_warning ("[%d] vpp handle 0x%llx, sid %u: " + "wrote %d bytes to %s (%p)", getpid (), vpp_handle, session_index, n_write, fifo_str, tx_fifo); } done: @@ -2887,16 +3114,18 @@ vppcom_session_write_ready (session_t * session, u32 session_index) /* Assumes caller has acquired spinlock: vcm->sessions_lockp */ if (PREDICT_FALSE (session->is_vep)) { - clib_warning ("[%d] ERROR: sid %u: cannot write to an " - "epoll session!", getpid (), session_index); + clib_warning ("[%d] ERROR: vpp handle 0x%llx, sid %u: " + "cannot write to an epoll session!", + getpid (), session->vpp_handle, session_index); rv = VPPCOM_EBADFD; goto done; } if (PREDICT_FALSE (session->is_listen)) { - clib_warning ("[%d] ERROR: sid %u: cannot write to a listen session!", - getpid (), session_index); + clib_warning ("[%d] ERROR: vpp handle 0x%llx, sid %u: " + "cannot write to a listen session!", + getpid (), session->vpp_handle, session_index); rv = VPPCOM_EBADFD; goto done; } @@ -2908,8 +3137,9 @@ vppcom_session_write_ready (session_t * session, u32 session_index) rv = ((state == STATE_DISCONNECT) ? VPPCOM_ECONNRESET : VPPCOM_ENOTCONN); - clib_warning ("[%d] ERROR: sid %u: %s session is not open! " - "state 0x%x (%s), returning %d (%s)", getpid (), + clib_warning ("[%d] ERROR: vpp handle 0x%llx, sid %u: " + "%s session is not open! state 0x%x (%s), " + "returning %d (%s)", getpid (), session->vpp_handle, session_index, is_server ? "server" : "client", state, vppcom_session_state_str (state), rv, vppcom_retval_str (rv)); @@ -2924,8 +3154,10 @@ vppcom_session_write_ready (session_t * session, u32 session_index) ready = svm_fifo_max_enqueue (tx_fifo); if (VPPCOM_DEBUG > 3) - clib_warning ("[%d] sid %u: peek %s (%p), ready = %d", getpid (), - session_index, fifo_str, tx_fifo, ready); + clib_warning ("[%d] vpp handle 0x%llx, sid %u: " + "peek %s (%p), ready = %d", getpid (), + session->vpp_handle, session_index, + fifo_str, tx_fifo, ready); if (ready == 0) { @@ -2941,10 +3173,11 @@ vppcom_session_write_ready (session_t * session, u32 session_index) if (VPPCOM_DEBUG > 1) { - clib_warning ("[%d] sid %u: Empty fifo with %s session " - "state 0x%x (%s)!\n" - " Setting state to %d (%s), returning %d (%s)", - getpid (), session_index, + clib_warning ("[%d] vpp handle 0x%llx, sid %u: " + "Empty fifo with %s session " + "state 0x%x (%s)! Setting state to 0x%x (%s), " + "returning %d (%s)", getpid (), + session->vpp_handle, session_index, is_server ? "server" : "client", state, vppcom_session_state_str (state), new_state, vppcom_session_state_str (new_state), @@ -3196,7 +3429,8 @@ vppcom_epoll_create (void) clib_spinlock_unlock (&vcm->sessions_lockp); if (VPPCOM_DEBUG > 0) - clib_warning ("[%d] Created vep_idx %u!", getpid (), vep_idx); + clib_warning ("[%d] Created vep_idx %u / sid %u!", + getpid (), vep_idx, vep_idx); return (vep_idx); } @@ -3641,7 +3875,7 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, break; case VPPCOM_ATTR_GET_PEER_ADDR: - if (buffer && buflen && (*buflen >= sizeof (*ep))) + if (buffer && buflen && (*buflen >= sizeof (*ep)) && ep->ip) { ep->vrf = session->vrf; ep->is_ip4 = session->peer_addr.is_ip4; @@ -3665,7 +3899,7 @@ vppcom_session_attr (uint32_t session_index, uint32_t op, break; case VPPCOM_ATTR_GET_LCL_ADDR: - if (buffer && buflen && (*buflen >= sizeof (*ep))) + if (buffer && buflen && (*buflen >= sizeof (*ep)) && ep->ip) { ep->vrf = session->vrf; ep->is_ip4 = session->lcl_addr.is_ip4;