ELOG additions for VCL
[vpp.git] / src / vcl / vppcom.c
index 2e3af1b..aff81f5 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>
@@ -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);
 }