Initial structure for VCL event logging.
[vpp.git] / src / vcl / vppcom.c
index 85bf1c2..dcf63d0 100644 (file)
@@ -23,6 +23,7 @@
 #include <vcl/vppcom.h>
 #include <vlib/unix/unix.h>
 #include <vppinfra/vec_bootstrap.h>
+#include <vppinfra/elog.h>
 
 #define vl_typedefs            /* define message structures */
 #include <vpp/api/vpe_all_api_h.h>
@@ -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 *
@@ -551,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;
@@ -1063,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;
 
@@ -1071,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);
 }
@@ -1086,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;
@@ -1112,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,
@@ -1135,18 +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, u32 session_index,
-                                  int retval)
+                                  u64 vpp_handle, u32 context, int retval)
 {
   vl_api_connect_session_reply_t *rmp;
   u32 len;
@@ -1154,8 +1217,17 @@ vppcom_send_connect_session_reply (session_t * session, u32 session_index,
 
   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;
@@ -1194,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;
     }
 
@@ -1438,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);
@@ -1449,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
@@ -1600,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)
@@ -1659,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);
@@ -2070,6 +2164,19 @@ 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))
@@ -2078,6 +2185,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;
@@ -2436,7 +2548,10 @@ vppcom_session_accept (uint32_t listen_session_index, vppcom_endpt_t * ep,
          vec_reset_length (a->new_segment_indices);
          rv = VNET_API_ERROR_URI_FIFO_CREATE_FAILED;
          vppcom_send_connect_session_reply (client_session,
-                                            client_session_index, rv);
+                                            client_session_index,
+                                            client_session->vpp_handle,
+                                            client_session->client_context,
+                                            rv);
          clib_spinlock_unlock (&vcm->sessions_lockp);
          rv = VPPCOM_ENOMEM;
          goto done;
@@ -2460,7 +2575,10 @@ vppcom_session_accept (uint32_t listen_session_index, vppcom_endpt_t * ep,
                        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,
-                                            client_session_index, rv);
+                                            client_session_index,
+                                            client_session->vpp_handle,
+                                            client_session->client_context,
+                                            rv);
          clib_spinlock_unlock (&vcm->sessions_lockp);
          rv = VPPCOM_ENOMEM;
          goto done;
@@ -2481,7 +2599,10 @@ vppcom_session_accept (uint32_t listen_session_index, vppcom_endpt_t * ep,
                        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,
-                                            client_session_index, rv);
+                                            client_session_index,
+                                            client_session->vpp_handle,
+                                            client_session->client_context,
+                                            rv);
          clib_spinlock_unlock (&vcm->sessions_lockp);
          rv = VPPCOM_ENOMEM;
          goto done;
@@ -2514,12 +2635,16 @@ vppcom_session_accept (uint32_t listen_session_index, vppcom_endpt_t * ep,
 #endif
       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)
@@ -2826,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;
 }
@@ -3737,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;
@@ -3761,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;