ldp/vcl: reduce debug verbosity
[vpp.git] / src / vcl / vppcom.c
index 34b663b..88a67dd 100644 (file)
@@ -464,8 +464,7 @@ vcl_session_bound_handler (vcl_worker_t * wrk, session_bound_msg_t * mp)
       session->tx_fifo = tx_fifo;
     }
 
-  VDBG (1, "VCL<%d>: vpp handle 0x%llx, sid %u: bind succeeded!",
-       getpid (), mp->handle, sid);
+  VDBG (0, "session %u [0x%llx]: listen succeeded!", sid, mp->handle);
   return sid;
 }
 
@@ -559,14 +558,17 @@ vppcom_wait_for_session_state_change (u32 session_index,
        }
 
       if (svm_msg_q_sub (wrk->app_event_queue, &msg, SVM_Q_NOWAIT, 0))
-       continue;
+       {
+         usleep (100);
+         continue;
+       }
       e = svm_msg_q_msg_data (wrk->app_event_queue, &msg);
       vcl_handle_mq_event (wrk, e);
       svm_msg_q_free_msg (wrk->app_event_queue, &msg);
     }
   while (clib_time_now (&wrk->clib_time) < timeout);
 
-  VDBG (0, "VCL<%d>: timeout waiting for state 0x%x (%s)", getpid (), state,
+  VDBG (0, "timeout waiting for state 0x%x (%s)", state,
        vppcom_session_state_str (state));
   vcl_evt (VCL_EVT_SESSION_TIMEOUT, session, session_state);
 
@@ -694,18 +696,103 @@ vcl_cleanup_bapi (void)
   vl_client_api_unmap ();
 }
 
-void
+static void
+vcl_cleanup_forked_child (vcl_worker_t * wrk, vcl_worker_t * child_wrk)
+{
+  vcl_worker_t *sub_child;
+  int tries = 0;
+
+  if (child_wrk->forked_child != ~0)
+    {
+      sub_child = vcl_worker_get_if_valid (child_wrk->forked_child);
+      if (sub_child)
+       {
+         /* Wait a bit, maybe the process is going away */
+         while (kill (sub_child->current_pid, 0) >= 0 && tries++ < 50)
+           usleep (1e3);
+         if (kill (sub_child->current_pid, 0) < 0)
+           vcl_cleanup_forked_child (child_wrk, sub_child);
+       }
+    }
+  vcl_worker_cleanup (child_wrk, 1 /* notify vpp */ );
+  VDBG (0, "Cleaned up wrk %u", child_wrk->wrk_index);
+  wrk->forked_child = ~0;
+}
+
+static struct sigaction old_sa;
+
+static void
+vcl_intercept_sigchld_handler (int signum, siginfo_t * si, void *uc)
+{
+  vcl_worker_t *wrk, *child_wrk;
+
+  if (vcl_get_worker_index () == ~0)
+    return;
+
+  sigaction (SIGCHLD, &old_sa, 0);
+
+  wrk = vcl_worker_get_current ();
+  if (wrk->forked_child == ~0)
+    return;
+
+  child_wrk = vcl_worker_get_if_valid (wrk->forked_child);
+  if (!child_wrk)
+    goto done;
+
+  if (si && si->si_pid != child_wrk->current_pid)
+    {
+      VDBG (0, "unexpected child pid %u", si->si_pid);
+      goto done;
+    }
+  vcl_cleanup_forked_child (wrk, child_wrk);
+
+done:
+  if (old_sa.sa_flags & SA_SIGINFO)
+    {
+      void (*fn) (int, siginfo_t *, void *) = old_sa.sa_sigaction;
+      fn (signum, si, uc);
+    }
+  else
+    {
+      void (*fn) (int) = old_sa.sa_handler;
+      if (fn)
+       fn (signum);
+    }
+}
+
+static void
+vcl_incercept_sigchld ()
+{
+  struct sigaction sa;
+  clib_memset (&sa, 0, sizeof (sa));
+  sa.sa_sigaction = vcl_intercept_sigchld_handler;
+  sa.sa_flags = SA_SIGINFO;
+  if (sigaction (SIGCHLD, &sa, &old_sa))
+    {
+      VERR ("couldn't intercept sigchld");
+      exit (-1);
+    }
+}
+
+static void
+vcl_app_pre_fork (void)
+{
+  vcl_incercept_sigchld ();
+}
+
+static void
 vcl_app_fork_child_handler (void)
 {
+  int rv, parent_wrk_index;
+  vcl_worker_t *parent_wrk;
   u8 *child_name;
-  int rv, parent_wrk;
 
-  VDBG (0, "initializing forked child");
+  parent_wrk_index = vcl_get_worker_index ();
+  VDBG (0, "initializing forked child with parent wrk %u", parent_wrk_index);
 
   /*
    * Allocate worker
    */
-  parent_wrk = vcl_get_worker_index ();
   vcl_set_worker_index (~0);
   if (!vcl_worker_alloc_and_init ())
     VERR ("couldn't allocate new worker");
@@ -729,21 +816,43 @@ vcl_app_fork_child_handler (void)
    * Register worker with vpp and share sessions
    */
   vcl_worker_register_with_vpp ();
+  parent_wrk = vcl_worker_get (parent_wrk_index);
   vcl_worker_share_sessions (parent_wrk);
+  parent_wrk->forked_child = vcl_get_worker_index ();
 
   VDBG (0, "forked child main worker initialized");
   vcm->forking = 0;
 }
 
-void
+static void
 vcl_app_fork_parent_handler (void)
 {
   vcm->forking = 1;
-
   while (vcm->forking)
     ;
 }
 
+/**
+ * Handle app exit
+ *
+ * Notify vpp of the disconnect and mark the worker as free. If we're the
+ * last worker, do a full cleanup otherwise, since we're probably a forked
+ * child, avoid syscalls as much as possible. We might've lost privileges.
+ */
+void
+vppcom_app_exit (void)
+{
+  if (!pool_elts (vcm->workers))
+    return;
+  vcl_worker_cleanup (vcl_worker_get_current (), 1 /* notify vpp */ );
+  vcl_set_worker_index (~0);
+  vcl_elog_stop (vcm);
+  if (vec_len (vcm->workers) == 1)
+    vl_client_disconnect_from_vlib ();
+  else
+    vl_client_send_disconnect (1 /* vpp should cleanup */ );
+}
+
 /*
  * VPPCOM Public API functions
  */
@@ -755,8 +864,8 @@ vppcom_app_create (char *app_name)
 
   if (vcm->is_init)
     {
-      clib_warning ("already initialized");
-      return -1;
+      VDBG (1, "already initialized");
+      return VPPCOM_EEXIST;
     }
 
   vcm->is_init = 1;
@@ -767,13 +876,14 @@ vppcom_app_create (char *app_name)
   vcm->main_pid = getpid ();
   vcm->app_name = format (0, "%s", app_name);
   vppcom_init_error_string_table ();
-  svm_fifo_segment_main_init (vcl_cfg->segment_baseva,
+  svm_fifo_segment_main_init (&vcm->segment_main, vcl_cfg->segment_baseva,
                              20 /* timeout in secs */ );
   pool_alloc (vcm->workers, vcl_cfg->max_workers);
   clib_spinlock_init (&vcm->workers_lock);
   clib_rwlock_init (&vcm->segment_table_lock);
-  pthread_atfork (NULL, vcl_app_fork_parent_handler,
+  pthread_atfork (vcl_app_pre_fork, vcl_app_fork_parent_handler,
                  vcl_app_fork_child_handler);
+  atexit (vppcom_app_exit);
 
   /* Allocate default worker */
   vcl_worker_alloc_and_init ();
@@ -816,9 +926,12 @@ vppcom_app_destroy (void)
   int rv;
   f64 orig_app_timeout;
 
+  if (!pool_elts (vcm->workers))
+    return;
+
   vcl_evt (VCL_EVT_DETACH, vcm);
 
-  if (vec_len (vcm->workers) == 1)
+  if (pool_elts (vcm->workers) == 1)
     {
       vppcom_app_send_detach ();
       orig_app_timeout = vcm->cfg.app_timeout;
@@ -828,15 +941,17 @@ vppcom_app_destroy (void)
       if (PREDICT_FALSE (rv))
        VDBG (0, "application detach timed out! returning %d (%s)", rv,
              vppcom_retval_str (rv));
+      vec_free (vcm->app_name);
+      vcl_worker_cleanup (vcl_worker_get_current (), 0 /* notify vpp */ );
     }
   else
     {
-      vcl_worker_cleanup ();
+      vcl_worker_cleanup (vcl_worker_get_current (), 1 /* notify vpp */ );
     }
 
+  vcl_set_worker_index (~0);
   vcl_elog_stop (vcm);
   vl_client_disconnect_from_vlib ();
-  vec_free (vcm->app_name);
 }
 
 int
@@ -887,7 +1002,7 @@ vppcom_session_close (uint32_t session_handle)
   state = session->session_state;
   vpp_handle = session->vpp_handle;
 
-  VDBG (0, "Closing session handle %u vpp handle %u", session_handle,
+  VDBG (1, "closing session handle %u vpp handle %u", session_handle,
        vpp_handle);
 
   if (is_vep)
@@ -961,8 +1076,7 @@ cleanup:
     }
   vcl_session_free (wrk, session);
 
-  VDBG (0, "session handle %u vpp handle %u removed", session_handle,
-       vpp_handle);
+  VDBG (0, "session handle %u [0x%llx] removed", session_handle, vpp_handle);
 
   vcl_evt (VCL_EVT_CLOSE, session, rv);
 
@@ -1022,29 +1136,22 @@ vppcom_session_listen (uint32_t listen_sh, uint32_t q_len)
   int rv;
 
   listen_session = vcl_session_get_w_handle (wrk, listen_sh);
-  if (!listen_session)
+  if (!listen_session || listen_session->is_vep)
     return VPPCOM_EBADFD;
 
   if (q_len == 0 || q_len == ~0)
     q_len = vcm->cfg.listen_queue_size;
 
-  if (listen_session->is_vep)
-    {
-      clib_warning ("VCL<%d>: ERROR: sid %u: cannot listen on an "
-                   "epoll session!", getpid (), listen_sh);
-      return VPPCOM_EBADFD;
-    }
-
   listen_vpp_handle = listen_session->vpp_handle;
   if (listen_session->session_state & STATE_LISTEN)
     {
-      VDBG (0, "VCL<%d>: vpp handle 0x%llx, sid %u: already in listen state!",
-           getpid (), listen_vpp_handle, listen_sh);
+      VDBG (0, "session %u [0x%llx]: already in listen state!",
+           listen_sh, listen_vpp_handle);
       return VPPCOM_OK;
     }
 
-  VDBG (0, "VCL<%d>: vpp handle 0x%llx, sid %u: sending VPP bind+listen "
-       "request...", getpid (), listen_vpp_handle, listen_sh);
+  VDBG (0, "session %u [0x%llx]: sending vpp listen request...",
+       listen_sh, listen_vpp_handle);
 
   /*
    * Send listen request to vpp and wait for reply
@@ -1057,9 +1164,9 @@ vppcom_session_listen (uint32_t listen_sh, uint32_t q_len)
   if (PREDICT_FALSE (rv))
     {
       listen_session = vcl_session_get_w_handle (wrk, listen_sh);
-      VDBG (0, "VCL<%d>: vpp handle 0x%llx, sid %u: bind+listen failed! "
-           "returning %d (%s)", getpid (), listen_session->vpp_handle,
-           listen_sh, rv, vppcom_retval_str (rv));
+      VDBG (0, "session %u [0x%llx]: listen failed! returning %d (%s)",
+           listen_sh, listen_session->vpp_handle, rv,
+           vppcom_retval_str (rv));
       return rv;
     }
 
@@ -1155,9 +1262,9 @@ handle:
     VCL_SESS_ATTR_SET (client_session->attr, VCL_SESS_ATTR_NONBLOCK);
 
   listen_vpp_handle = listen_session->vpp_handle;
-  VDBG (0, "VCL<%d>: vpp handle 0x%llx, sid %u: Got a client request! "
+  VDBG (1, "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_handle,
+       listen_vpp_handle, listen_session_handle,
        client_session->vpp_handle, client_session_index,
        flags, VCL_SESS_ATTR_TEST (client_session->attr,
                                   VCL_SESS_ATTR_NONBLOCK));
@@ -1183,16 +1290,12 @@ handle:
   vcl_send_session_accepted_reply (vpp_evt_q, client_session->client_context,
                                   client_session->vpp_handle, 0);
 
-  VDBG (0, "VCL<%d>: vpp handle 0x%llx, sid %u: accepted vpp handle 0x%llx, "
-       "sid %u connection from peer %s address %U port %u to local %s "
-       "address %U port %u", getpid (), listen_vpp_handle,
-       listen_session_handle, client_session->vpp_handle,
-       client_session_index,
-       client_session->transport.is_ip4 ? "IPv4" : "IPv6",
+  VDBG (0, "listener %u [0x%llx] accepted %u [0x%llx] peer: %U:%u "
+       "local: %U:%u", listen_session_handle, listen_vpp_handle,
+       client_session_index, client_session->vpp_handle,
        format_ip46_address, &client_session->transport.rmt_ip,
        client_session->transport.is_ip4 ? IP46_TYPE_IP4 : IP46_TYPE_IP6,
        clib_net_to_host_u16 (client_session->transport.rmt_port),
-       client_session->transport.is_ip4 ? "IPv4" : "IPv6",
        format_ip46_address, &client_session->transport.lcl_ip,
        client_session->transport.is_ip4 ? IP46_TYPE_IP4 : IP46_TYPE_IP6,
        clib_net_to_host_u16 (client_session->transport.lcl_port));
@@ -1549,8 +1652,9 @@ vcl_is_tx_evt_for_session (session_event_t * e, u32 sid, u8 is_ct)
     return (e->event_type == SESSION_IO_EVT_CT_RX);
 }
 
-int
-vppcom_session_write (uint32_t session_handle, void *buf, size_t n)
+static inline int
+vppcom_session_write_inline (uint32_t session_handle, void *buf, size_t n,
+                            u8 is_flush)
 {
   vcl_worker_t *wrk = vcl_worker_get_current ();
   int rv, n_write, is_nonblocking;
@@ -1617,6 +1721,9 @@ vppcom_session_write (uint32_t session_handle, void *buf, size_t n)
 
   ASSERT (FIFO_EVENT_APP_TX + 1 == SESSION_IO_EVT_CT_TX);
   et = FIFO_EVENT_APP_TX + vcl_session_is_ct (s);
+  if (is_flush && !vcl_session_is_ct (s))
+    et = SESSION_IO_EVT_TX_FLUSH;
+
   if (s->is_dgram)
     n_write = app_send_dgram_raw (tx_fifo, &s->transport,
                                  s->vpp_evt_q, buf, n, et, SVM_Q_WAIT);
@@ -1632,6 +1739,13 @@ vppcom_session_write (uint32_t session_handle, void *buf, size_t n)
   return n_write;
 }
 
+int
+vppcom_session_write (uint32_t session_handle, void *buf, size_t n)
+{
+  return vppcom_session_write_inline (session_handle, buf, n,
+                                     0 /* is_flush */ );
+}
+
 static vcl_session_t *
 vcl_ct_session_get_from_fifo (vcl_worker_t * wrk, svm_fifo_t * f, u8 type)
 {
@@ -3229,7 +3343,7 @@ vppcom_session_sendto (uint32_t session_handle, void *buffer,
            getpid (), flags, flags);
     }
 
-  return (vppcom_session_write (session_handle, buffer, buflen));
+  return (vppcom_session_write_inline (session_handle, buffer, buflen, 1));
 }
 
 int