ldp/vcl: reduce debug verbosity

Also cleanup some ldp debug code.

Change-Id: I23d1b9d744289244f4778f623702fc2b5d6fcd8b
Signed-off-by: Florin Coras <fcoras@cisco.com>

diff --git a/src/vcl/ldp.c b/src/vcl/ldp.c
index c3dc64a..d538770 100644 (file)
--- a/src/vcl/ldp.c
+++ b/src/vcl/ldp.c
@@ -112,7 +112,7 @@ typedef struct
 
 #define LDBG(_lvl, _fmt, _args...)                                     \
   if (ldp->debug > _lvl)                                               \
-    clib_warning (_fmt, ##_args)
+    clib_warning ("ldp<%d>: " _fmt, getpid(), ##_args)
 
 static ldp_main_t ldp_main = {
   .sid_bit_val = (1 << LDP_SID_BIT_MIN),
@@ -261,9 +261,8 @@ ldp_init (void)
       ldp->vcl_needs_real_epoll = 0;
       if (rv == VPPCOM_EEXIST)
        return 0;
-      LDBG (2, "\nLDP<%d>: ERROR: ldp_init: vppcom_app_create()"
-           " failed!  rv = %d (%s)\n",
-           getpid (), rv, vppcom_retval_str (rv));
+      LDBG (2, "\nERROR: ldp_init: vppcom_app_create()"
+           " failed!  rv = %d (%s)\n", rv, vppcom_retval_str (rv));
       ldp->init = 0;
       return rv;
     }
@@ -282,8 +281,8 @@ ldp_init (void)
       else
        {
          ldp->debug = tmp;
-         LDBG (0, "LDP<%d>: configured LDP debug level (%u) from env var "
-               LDP_ENV_DEBUG "!", getpid (), ldp->debug);
+         LDBG (0, "configured LDP debug level (%u) from env var "
+               LDP_ENV_DEBUG "!", ldp->debug);
        }
     }
 
@@ -291,8 +290,8 @@ ldp_init (void)
   if (env_var_str)
     {
       ldp_set_app_name (env_var_str);
-      LDBG (0, "LDP<%d>: configured LDP app name (%s) from the env var "
-           LDP_ENV_APP_NAME "!", getpid (), ldp->app_name);
+      LDBG (0, "configured LDP app name (%s) from the env var "
+           LDP_ENV_APP_NAME "!", ldp->app_name);
     }
 
   env_var_str = getenv (LDP_ENV_SID_BIT);
@@ -333,15 +332,15 @@ ldp_init (void)
          ldp->sid_bit_val = (1 << sb);
          ldp->sid_bit_mask = ldp->sid_bit_val - 1;
 
-         LDBG (0, "LDP<%d>: configured LDP sid bit (%u) from "
-               LDP_ENV_SID_BIT "!  sid bit value %d (0x%x)", getpid (), sb,
+         LDBG (0, "configured LDP sid bit (%u) from "
+               LDP_ENV_SID_BIT "!  sid bit value %d (0x%x)", sb,
                ldp->sid_bit_val, ldp->sid_bit_val);
        }
     }
 
   clib_time_init (&ldpw->clib_time);
   clib_rwlock_init (&ldp->fd_table_lock);
-  LDBG (0, "LDP<%d>: LDP initialization: done!", getpid ());
+  LDBG (0, "LDP initialization: done!");
 
   return 0;
 }
@@ -350,7 +349,6 @@ int
 close (int fd)
 {
   int rv, refcnt;
-  const char *func_str;
   u32 sid = ldp_sid_from_fd (fd);
 
   if ((errno = -ldp_init ()))
@@ -360,14 +358,11 @@ close (int fd)
     {
       int epfd;
 
-      func_str = "vppcom_session_attr[GET_LIBC_EPFD]";
       epfd = vppcom_session_attr (sid, VPPCOM_ATTR_GET_LIBC_EPFD, 0, 0);
       if (epfd > 0)
        {
-         func_str = "libc_close";
-
-         LDBG (0, "LDP<%d>: fd %d (0x%x): calling %s(): epfd %u (0x%x)",
-               getpid (), fd, fd, func_str, epfd, epfd);
+         LDBG (0, "fd %d (0x%x): calling libc_close: epfd %u (0x%x)",
+               fd, fd, epfd, epfd);
 
          rv = libc_close (epfd);
          if (rv < 0)
@@ -386,10 +381,8 @@ close (int fd)
          goto done;
        }
 
-      func_str = "vppcom_session_close";
-
-      LDBG (0, "LDP<%d>: fd %d (0x%x): calling %s(): sid %u (0x%x)",
-           getpid (), fd, fd, func_str, sid, sid);
+      LDBG (0, "fd %d (0x%x): calling vppcom_session_close: sid %u (0x%x)",
+           fd, fd, sid, sid);
 
       refcnt = vppcom_session_attr (sid, VPPCOM_ATTR_GET_REFCNT, 0, 0);
       rv = vppcom_session_close (sid);
@@ -403,30 +396,13 @@ close (int fd)
     }
   else
     {
-      func_str = "libc_close";
-
-      LDBG (0, "LDP<%d>: fd %d (0x%x): calling %s()", getpid (), fd, fd,
-           func_str);
-
+      LDBG (0, "fd %d (0x%x): calling libc_close", fd, fd);
       rv = libc_close (fd);
     }
 
 done:
-  if (LDP_DEBUG > 0)
-    {
-      if (rv < 0)
-       {
-         int errno_val = errno;
-         perror (func_str);
-         clib_warning ("LDP<%d>: ERROR: fd %d (0x%x): %s() failed! "
-                       "rv %d, errno = %d", getpid (), fd, fd,
-                       func_str, rv, errno_val);
-         errno = errno_val;
-       }
-      else
-       clib_warning ("LDP<%d>: fd %d (0x%x): returning %d (0x%x)",
-                     getpid (), fd, fd, rv, rv);
-    }
+
+  LDBG (1, "fd %d (0x%x): returning %d (0x%x)", fd, fd, rv, rv);
   return rv;
 }
 
@@ -434,7 +410,6 @@ ssize_t
 read (int fd, void *buf, size_t nbytes)
 {
   ssize_t size;
-  const char *func_str;
   u32 sid = ldp_sid_from_fd (fd);
 
   if ((errno = -ldp_init ()))
@@ -442,12 +417,8 @@ read (int fd, void *buf, size_t nbytes)
 
   if (sid != INVALID_SESSION_ID)
     {
-      func_str = "vppcom_session_read";
-
-      if (LDP_DEBUG > 2)
-       clib_warning ("LDP<%d>: fd %d (0x%x): calling %s(): "
-                     "sid %u (0x%x), buf %p, nbytes %u", getpid (),
-                     fd, fd, func_str, sid, sid, buf, nbytes);
+      LDBG (2, "fd %d (0x%x): calling vppcom_session_read(): sid %u (0x%x),"
+           " buf %p, nbytes %u", fd, fd, sid, sid, buf, nbytes);
 
       size = vppcom_session_read (sid, buf, nbytes);
       if (size < 0)
@@ -458,38 +429,19 @@ read (int fd, void *buf, size_t nbytes)
     }
   else
     {
-      func_str = "libc_read";
-
-      if (LDP_DEBUG > 2)
-       clib_warning ("LDP<%d>: fd %d (0x%x): calling %s(): "
-                     "buf %p, nbytes %u", getpid (),
-                     fd, fd, func_str, buf, nbytes);
+      LDBG (2, "fd %d (0x%x): calling libc_read(): buf %p, nbytes %u",
+           fd, fd, buf, nbytes);
 
       size = libc_read (fd, buf, nbytes);
     }
 
-  if (LDP_DEBUG > 2)
-    {
-      if (size < 0)
-       {
-         int errno_val = errno;
-         perror (func_str);
-         clib_warning ("LDP<%d>: ERROR: fd %d (0x%x): %s() failed! "
-                       "rv %d, errno = %d", getpid (), fd, fd,
-                       func_str, size, errno_val);
-         errno = errno_val;
-       }
-      else
-       clib_warning ("LDP<%d>: fd %d (0x%x): returning %d (0x%x)",
-                     getpid (), fd, fd, size, size);
-    }
+  LDBG (2, "fd %d (0x%x): returning %d (0x%x)", fd, fd, size, size);
   return size;
 }
 
 ssize_t
 readv (int fd, const struct iovec * iov, int iovcnt)
 {
-  const char *func_str;
   ssize_t size = 0;
   u32 sid = ldp_sid_from_fd (fd);
   int rv = 0, i, total = 0;
@@ -499,16 +451,13 @@ readv (int fd, const struct iovec * iov, int iovcnt)
 
   if (sid != INVALID_SESSION_ID)
     {
-      func_str = "vppcom_session_read";
       do
        {
          for (i = 0; i < iovcnt; ++i)
            {
-             if (LDP_DEBUG > 2)
-               clib_warning ("LDP<%d>: fd %d (0x%x): calling %s() [%d]: "
-                             "sid %u (0x%x), iov %p, iovcnt %d, total %d",
-                             getpid (), fd, fd, func_str, i, sid, sid,
-                             iov, iovcnt, total);
+             LDBG (2, "fd %d (0x%x): calling vppcom_session_read() [%d]:"
+                   " sid %u (0x%x), iov %p, iovcnt %d, total %d", fd, fd, i,
+                   sid, sid, iov, iovcnt, total);
 
              rv = vppcom_session_read (sid, iov[i].iov_base, iov[i].iov_len);
              if (rv < 0)
@@ -518,11 +467,8 @@ readv (int fd, const struct iovec * iov, int iovcnt)
                  total += rv;
                  if (rv < iov[i].iov_len)
                    {
-                     if (LDP_DEBUG > 2)
-                       clib_warning ("LDP<%d>: fd %d (0x%x): "
-                                     "rv (%d) < iov[%d].iov_len (%d)",
-                                     getpid (), fd, fd, rv, i,
-                                     iov[i].iov_len);
+                     LDBG (2, "fd %d (0x%x): rv (%d) < iov[%d].iov_len (%d)",
+                           fd, fd, rv, i, iov[i].iov_len);
                      break;
                    }
                }
@@ -540,37 +486,20 @@ readv (int fd, const struct iovec * iov, int iovcnt)
     }
   else
     {
-      func_str = "libc_readv";
-
-      if (LDP_DEBUG > 2)
-       clib_warning ("LDP<%d>: fd %d (0x%x): calling %s(): "
-                     "iov %p, iovcnt %d", getpid (), fd, fd, iov, iovcnt);
+      LDBG (2, "fd %d (0x%x): calling libc_readv(): iov %p, iovcnt %d", fd,
+           fd, iov, iovcnt);
 
       size = libc_readv (fd, iov, iovcnt);
     }
 
-  if (LDP_DEBUG > 2)
-    {
-      if (size < 0)
-       {
-         int errno_val = errno;
-         perror (func_str);
-         clib_warning ("LDP<%d>: ERROR: fd %d (0x%x): %s() failed! "
-                       "rv %d, errno = %d", getpid (), fd, fd,
-                       func_str, size, errno_val);
-         errno = errno_val;
-       }
-      else
-       clib_warning ("LDP<%d>: fd %d (0x%x): returning %d (0x%x)",
-                     getpid (), fd, fd, size, size);
-    }
+
+  LDBG (2, "fd %d (0x%x): returning %d (0x%x)", fd, fd, size, size);
   return size;
 }
 
 ssize_t
 write (int fd, const void *buf, size_t nbytes)
 {
-  const char *func_str;
   ssize_t size = 0;
   u32 sid = ldp_sid_from_fd (fd);
 
@@ -579,12 +508,8 @@ write (int fd, const void *buf, size_t nbytes)
 
   if (sid != INVALID_SESSION_ID)
     {
-      func_str = "vppcom_session_write";
-
-      if (LDP_DEBUG > 2)
-       clib_warning ("LDP<%d>: fd %d (0x%x): calling %s(): "
-                     "sid %u (0x%x), buf %p, nbytes %u", getpid (),
-                     fd, fd, func_str, sid, sid, buf, nbytes);
+      LDBG (2, "fd %d (0x%x): calling vppcom_session_write(): sid %u (0x%x), "
+           "buf %p, nbytes %u", fd, fd, sid, sid, buf, nbytes);
 
       size = vppcom_session_write (sid, (void *) buf, nbytes);
       if (size < 0)
@@ -595,31 +520,13 @@ write (int fd, const void *buf, size_t nbytes)
     }
   else
     {
-      func_str = "libc_write";
-
-      if (LDP_DEBUG > 2)
-       clib_warning ("LDP<%d>: fd %d (0x%x): calling %s(): "
-                     "buf %p, nbytes %u", getpid (),
-                     fd, fd, func_str, buf, nbytes);
+      LDBG (2, "fd %d (0x%x): calling libc_write(): buf %p, nbytes %u",
+           fd, fd, buf, nbytes);
 
       size = libc_write (fd, buf, nbytes);
     }
 
-  if (LDP_DEBUG > 2)
-    {
-      if (size < 0)
-       {
-         int errno_val = errno;
-         perror (func_str);
-         clib_warning ("LDP<%d>: ERROR: fd %d (0x%x): %s() failed! "
-                       "rv %d, errno = %d", getpid (), fd, fd,
-                       func_str, size, errno_val);
-         errno = errno_val;
-       }
-      else
-       clib_warning ("LDP<%d>: fd %d (0x%x): returning %d (0x%x)",
-                     getpid (), fd, fd, size, size);
-    }
+  LDBG (2, "fd %d (0x%x): returning %d (0x%x)", fd, fd, size, size);
   return size;
 }
 
@@ -734,8 +641,8 @@ fcntl (int fd, int cmd, ...)
        {
        case F_SETFL:
          func_str = "vppcom_session_attr[SET_FLAGS]";
-         LDBG (2, "LDP<%d>: fd %d (0x%x): calling %s(): sid %u (0x%x) "
-               "flags %d (0x%x), size %d", getpid (), fd, fd, func_str, sid,
+         LDBG (2, "fd %d (0x%x): calling %s(): sid %u (0x%x) "
+               "flags %d (0x%x), size %d", fd, fd, func_str, sid,
                sid, flags, flags, size);
 
          rv = vppcom_session_attr (sid, VPPCOM_ATTR_SET_FLAGS, &flags,
@@ -744,16 +651,16 @@ fcntl (int fd, int cmd, ...)
 
        case F_GETFL:
          func_str = "vppcom_session_attr[GET_FLAGS]";
-         LDBG (2, "LDP<%d>: fd %d (0x%x): calling %s(): sid %u (0x%x), "
-               "flags %d (0x%x), size %d", getpid (), fd, fd, func_str, sid,
+         LDBG (2, "fd %d (0x%x): calling %s(): sid %u (0x%x), "
+               "flags %d (0x%x), size %d", fd, fd, func_str, sid,
                sid, flags, flags, size);
 
          rv = vppcom_session_attr (sid, VPPCOM_ATTR_GET_FLAGS, &flags,
                                    &size);
          if (rv == VPPCOM_OK)
            {
-             LDBG (2, "LDP<%d>: fd %d (0x%x), cmd %d (F_GETFL): %s() "
-                   "returned flags %d (0x%x)", getpid (), fd, fd, cmd,
+             LDBG (2, "fd %d (0x%x), cmd %d (F_GETFL): %s() "
+                   "returned flags %d (0x%x)", fd, fd, cmd,
                    func_str, flags, flags);
              rv = flags;
            }
@@ -777,9 +684,7 @@ fcntl (int fd, int cmd, ...)
     {
       func_str = "libc_vfcntl";
 
-      if (LDP_DEBUG > 2)
-       clib_warning ("LDP<%d>: fd %d (0x%x): calling %s(): cmd %d",
-                     getpid (), fd, fd, func_str, cmd);
+      LDBG (2, "fd %d (0x%x): calling %s(): cmd %d", fd, fd, func_str, cmd);
 
       rv = libc_vfcntl (fd, cmd, ap);
     }
@@ -920,8 +825,7 @@ ldp_pselect (int nfds, fd_set * __restrict readfds,
       /* select as fine grained sleep */
       if (!nfds)
        {
-         LDBG (3, "LDP<%d>: sleeping for %.02f seconds", getpid (),
-               time_out);
+         LDBG (3, "sleeping for %.02f seconds", time_out);
 
          time_out += clib_time_now (&ldpw->clib_time);
          while (clib_time_now (&ldpw->clib_time) < time_out)
@@ -942,8 +846,8 @@ ldp_pselect (int nfds, fd_set * __restrict readfds,
     {
       func_str = "libc_pselect";
 
-      LDBG (3, "LDP<%d>: calling %s(): nfds %d, readfds %p, writefds %p, "
-           "exceptfds %p, timeout %p, sigmask %p", getpid (), func_str, nfds,
+      LDBG (3, "calling %s(): nfds %d, readfds %p, writefds %p, "
+           "exceptfds %p, timeout %p, sigmask %p", func_str, nfds,
            readfds, writefds, exceptfds, timeout, sigmask);
 
       rv = libc_pselect (nfds, readfds, writefds, exceptfds,
@@ -976,8 +880,7 @@ ldp_pselect (int nfds, fd_set * __restrict readfds,
        if (fd > nfds)
          break;
         sid = ldp_sid_from_fd (fd);
-        LDBG (3, "LDP<%d>: readfds: fd %d (0x%x), sid %u (0x%x)",
-              getpid (), fd, fd, sid, sid);
+        LDBG (3, "readfds: fd %d (0x%x), sid %u (0x%x)", fd, fd, sid, sid);
         if (sid == INVALID_SESSION_ID)
           clib_bitmap_set_no_check (ldpw->libc_rd_bitmap, fd, 1);
         else
@@ -992,8 +895,8 @@ ldp_pselect (int nfds, fd_set * __restrict readfds,
       libc_bits_set = clib_bitmap_last_set (ldpw->libc_rd_bitmap) + 1;
       libc_bits = (libc_bits_set > libc_bits) ? libc_bits_set : libc_bits;
 
-      LDBG (3, "LDP<%d>: readfds: sid_bits_set %d, sid_bits %d, "
-           "libc_bits_set %d, libc_bits %d", getpid (), sid_bits_set,
+      LDBG (3, "readfds: sid_bits_set %d, sid_bits %d, "
+           "libc_bits_set %d, libc_bits %d", sid_bits_set,
            sid_bits, libc_bits_set, libc_bits);
     }
   if (writefds)
@@ -1009,8 +912,7 @@ ldp_pselect (int nfds, fd_set * __restrict readfds,
        if (fd > nfds)
          break;
         sid = ldp_sid_from_fd (fd);
-        LDBG (3, "LDP<%d>: writefds: fd %d (0x%x), sid %u (0x%x)",
-                        getpid (), fd, fd, sid, sid);
+        LDBG (3, "writefds: fd %d (0x%x), sid %u (0x%x)", fd, fd, sid, sid);
         if (sid == INVALID_SESSION_ID)
           clib_bitmap_set_no_check (ldpw->libc_wr_bitmap, fd, 1);
         else
@@ -1025,8 +927,8 @@ ldp_pselect (int nfds, fd_set * __restrict readfds,
       libc_bits_set = clib_bitmap_last_set (ldpw->libc_wr_bitmap) + 1;
       libc_bits = (libc_bits_set > libc_bits) ? libc_bits_set : libc_bits;
 
-      LDBG (3, "LDP<%d>: writefds: sid_bits_set %d, sid_bits %d, "
-           "libc_bits_set %d, libc_bits %d", getpid (),
+      LDBG (3, "writefds: sid_bits_set %d, sid_bits %d, "
+           "libc_bits_set %d, libc_bits %d",
            sid_bits_set, sid_bits, libc_bits_set, libc_bits);
     }
   if (exceptfds)
@@ -1042,8 +944,7 @@ ldp_pselect (int nfds, fd_set * __restrict readfds,
        if (fd > nfds)
          break;
         sid = ldp_sid_from_fd (fd);
-        LDBG (3, "LDP<%d>: exceptfds: fd %d (0x%x), sid %u (0x%x)",
-                        getpid (), fd, fd, sid, sid);
+        LDBG (3, "exceptfds: fd %d (0x%x), sid %u (0x%x)", fd, fd, sid, sid);
         if (sid == INVALID_SESSION_ID)
           clib_bitmap_set_no_check (ldpw->libc_ex_bitmap, fd, 1);
         else
@@ -1058,8 +959,8 @@ ldp_pselect (int nfds, fd_set * __restrict readfds,
       libc_bits_set = clib_bitmap_last_set (ldpw->libc_ex_bitmap) + 1;
       libc_bits = (libc_bits_set > libc_bits) ? libc_bits_set : libc_bits;
 
-      LDBG (3, "LDP<%d>: exceptfds: sid_bits_set %d, sid_bits %d, "
-           "libc_bits_set %d, libc_bits %d", getpid (),
+      LDBG (3, "exceptfds: sid_bits_set %d, sid_bits %d, "
+           "libc_bits_set %d, libc_bits %d",
            sid_bits_set, sid_bits, libc_bits_set, libc_bits);
     }
 
@@ -1264,9 +1165,8 @@ socket (int domain, int type, int protocol)
 
       func_str = "vppcom_session_create";
 
-      LDBG (0, "LDP<%d>: : calling %s(): proto %u (%s), is_nonblocking %u",
-           getpid (), func_str, proto, vppcom_proto_str (proto),
-           is_nonblocking);
+      LDBG (0, "calling %s(): proto %u (%s), is_nonblocking %u",
+           func_str, proto, vppcom_proto_str (proto), is_nonblocking);
 
       sid = vppcom_session_create (proto, is_nonblocking);
       if (sid < 0)
@@ -1290,7 +1190,7 @@ socket (int domain, int type, int protocol)
     {
       func_str = "libc_socket";
 
-      LDBG (0, "LDP<%d>: : calling %s()", getpid (), func_str);
+      LDBG (0, "calling %s()", func_str);
 
       rv = libc_socket (domain, type, protocol);
     }
@@ -1307,7 +1207,7 @@ socket (int domain, int type, int protocol)
          errno = errno_val;
        }
       else
-       clib_warning ("LDP<%d>: : returning fd %d (0x%x)", getpid (), rv, rv);
+       clib_warning ("returning fd %d (0x%x)", getpid (), rv, rv);
     }
   return rv;
 }
@@ -1342,7 +1242,7 @@ socketpair (int domain, int type, int protocol, int fds[2])
     {
       func_str = "libc_socket";
 
-      LDBG (1, "LDP<%d>: : calling %s()", getpid (), func_str);
+      LDBG (1, "calling %s()", func_str);
 
       rv = libc_socketpair (domain, type, protocol, fds);
     }
@@ -1368,7 +1268,6 @@ int
 bind (int fd, __CONST_SOCKADDR_ARG addr, socklen_t len)
 {
   int rv;
-  const char *func_str;
   u32 sid = ldp_sid_from_fd (fd);
 
   if ((errno = -ldp_init ()))
@@ -1378,8 +1277,6 @@ bind (int fd, __CONST_SOCKADDR_ARG addr, socklen_t len)
     {
       vppcom_endpt_t ep;
 
-      func_str = "vppcom_session_bind";
-
       switch (addr->sa_family)
        {
        case AF_INET:
@@ -1420,10 +1317,8 @@ bind (int fd, __CONST_SOCKADDR_ARG addr, socklen_t len)
          rv = -1;
          goto done;
        }
-      if (LDP_DEBUG > 0)
-       clib_warning ("LDP<%d>: fd %d (0x%x): calling %s(): sid %u (0x%x), "
-                     "addr %p, len %u",
-                     getpid (), fd, fd, func_str, sid, sid, addr, len);
+      LDBG (0, "fd %d (0x%x): calling vppcom_session_bind(): "
+           "sid %u (0x%x), addr %p, len %u", fd, fd, sid, sid, addr, len);
 
       rv = vppcom_session_bind (sid, &ep);
       if (rv != VPPCOM_OK)
@@ -1434,32 +1329,15 @@ bind (int fd, __CONST_SOCKADDR_ARG addr, socklen_t len)
     }
   else
     {
-      func_str = "libc_bind";
-
-      if (LDP_DEBUG > 0)
-       clib_warning ("LDP<%d>: fd %d (0x%x): calling %s(): "
-                     "addr %p, len %u",
-                     getpid (), fd, fd, func_str, addr, len);
+      LDBG (0, "fd %d (0x%x): calling libc_bind(): addr %p, len %u",
+           fd, fd, addr, len);
 
       rv = libc_bind (fd, addr, len);
     }
 
 done:
-  if (LDP_DEBUG > 0)
-    {
-      if (rv < 0)
-       {
-         int errno_val = errno;
-         perror (func_str);
-         clib_warning ("LDP<%d>: ERROR: fd %d (0x%x): %s() failed! "
-                       "rv %d, errno = %d", getpid (), fd, fd,
-                       func_str, rv, errno_val);
-         errno = errno_val;
-       }
-      else
-       clib_warning ("LDP<%d>: fd %d (0x%x): returning %d (0x%x)",
-                     getpid (), fd, fd, rv, rv);
-    }
+  LDBG (1, "fd %d (0x%x): returning %d", fd, fd, rv);
+
   return rv;
 }
 
@@ -1583,7 +1461,6 @@ int
 connect (int fd, __CONST_SOCKADDR_ARG addr, socklen_t len)
 {
   int rv;
-  const char *func_str = __func__;
   u32 sid = ldp_sid_from_fd (fd);
 
   if ((errno = -ldp_init ()))
@@ -1602,8 +1479,6 @@ connect (int fd, __CONST_SOCKADDR_ARG addr, socklen_t len)
     {
       vppcom_endpt_t ep;
 
-      func_str = "vppcom_session_connect";
-
       switch (addr->sa_family)
        {
        case AF_INET:
@@ -1644,10 +1519,8 @@ connect (int fd, __CONST_SOCKADDR_ARG addr, socklen_t len)
          rv = -1;
          goto done;
        }
-      if (LDP_DEBUG > 0)
-       clib_warning ("LDP<%d>: fd %d (0x%x): calling %s(): sid %u (0x%x) "
-                     "addr %p len %u",
-                     getpid (), fd, fd, func_str, sid, sid, addr, len);
+      LDBG (0, "fd %d (0x%x): calling vppcom_session_connect(): sid %u (0x%x)"
+           " addr %p len %u", fd, fd, sid, sid, addr, len);
 
       rv = vppcom_session_connect (sid, &ep);
       if (rv != VPPCOM_OK)
@@ -1658,32 +1531,14 @@ connect (int fd, __CONST_SOCKADDR_ARG addr, socklen_t len)
     }
   else
     {
-      func_str = "libc_connect";
-
-      if (LDP_DEBUG > 0)
-       clib_warning ("LDP<%d>: fd %d (0x%x): calling %s(): "
-                     "addr %p, len %u",
-                     getpid (), fd, fd, func_str, addr, len);
+      LDBG (0, "fd %d (0x%x): calling libc_connect(): addr %p, len %u",
+           fd, fd, addr, len);
 
       rv = libc_connect (fd, addr, len);
     }
 
 done:
-  if (LDP_DEBUG > 0)
-    {
-      if (rv < 0)
-       {
-         int errno_val = errno;
-         perror (func_str);
-         clib_warning ("LDP<%d>: ERROR: fd %d (0x%x): %s() failed! "
-                       "rv %d, errno = %d", getpid (), fd, fd,
-                       func_str, rv, errno_val);
-         errno = errno_val;
-       }
-      else
-       clib_warning ("LDP<%d>: fd %d (0x%x): returning %d (0x%x)",
-                     getpid (), fd, fd, rv, rv);
-    }
+  LDBG (1, "fd %d (0x%x): returning %d (0x%x)", fd, fd, rv, rv);
   return rv;
 }
 
@@ -2865,7 +2720,6 @@ int
 listen (int fd, int n)
 {
   int rv;
-  const char *func_str;
   u32 sid = ldp_sid_from_fd (fd);
 
   if ((errno = -ldp_init ()))
@@ -2873,10 +2727,8 @@ listen (int fd, int n)
 
   if (sid != INVALID_SESSION_ID)
     {
-      func_str = "vppcom_session_listen";
-
-      LDBG (0, "LDP<%d>: fd %d (0x%x): calling %s(): sid %u (0x%x), n %d",
-           getpid (), fd, fd, func_str, sid, sid, n);
+      LDBG (0, "fd %d (0x%x): calling vppcom_session_listen():"
+           " sid %u (0x%x), n %d", fd, fd, sid, sid, n);
 
       rv = vppcom_session_listen (sid, n);
       if (rv != VPPCOM_OK)
@@ -2887,29 +2739,12 @@ listen (int fd, int n)
     }
   else
     {
-      func_str = "libc_listen";
-
-      LDBG (0, "LDP<%d>: fd %d (0x%x): calling %s(): n %d", getpid (), fd,
-           fd, func_str, n);
+      LDBG (0, "fd %d (0x%x): calling libc_listen(): n %d", fd, fd, n);
 
       rv = libc_listen (fd, n);
     }
 
-  if (LDP_DEBUG > 0)
-    {
-      if (rv < 0)
-       {
-         int errno_val = errno;
-         perror (func_str);
-         clib_warning ("LDP<%d>: ERROR: fd %d (0x%x): %s() failed! "
-                       "rv %d, errno = %d", getpid (), fd, fd,
-                       func_str, rv, errno_val);
-         errno = errno_val;
-       }
-      else
-       clib_warning ("LDP<%d>: fd %d (0x%x): returning %d (0x%x)",
-                     getpid (), fd, fd, rv, rv);
-    }
+  LDBG (1, "fd %d (0x%x): returning %d (0x%x)", fd, fd, rv, rv);
   return rv;
 }
 
@@ -2918,7 +2753,6 @@ ldp_accept4 (int listen_fd, __SOCKADDR_ARG addr,
             socklen_t * __restrict addr_len, int flags)
 {
   int rv;
-  const char *func_str;
   u32 listen_sid = ldp_sid_from_fd (listen_fd);
   int accept_sid;
 
@@ -2932,13 +2766,9 @@ ldp_accept4 (int listen_fd, __SOCKADDR_ARG addr,
       memset (&ep, 0, sizeof (ep));
       ep.ip = src_addr;
 
-      func_str = "vppcom_session_accept";
-
-      if (LDP_DEBUG > 0)
-       clib_warning ("LDP<%d>: listen fd %d (0x%x): calling %s(): "
-                     "listen sid %u (0x%x), ep %p, flags 0x%x",
-                     getpid (), listen_fd, listen_fd, func_str,
-                     listen_sid, listen_sid, ep, flags);
+      LDBG (0, "listen fd %d (0x%x): calling vppcom_session_accept:"
+           " listen sid %u (0x%x), ep %p, flags 0x%x", listen_fd,
+           listen_fd, listen_sid, listen_sid, ep, flags);
 
       accept_sid = vppcom_session_accept (listen_sid, &ep, flags);
       if (accept_sid < 0)
@@ -2957,12 +2787,6 @@ ldp_accept4 (int listen_fd, __SOCKADDR_ARG addr,
            }
          else
            {
-             func_str = "ldp_fd_from_sid";
-             if (LDP_DEBUG > 0)
-               clib_warning ("LDP<%d>: listen fd %d (0x%x): calling %s(): "
-                             "accept sid %u (0x%x), ep %p, flags 0x%x",
-                             getpid (), listen_fd, listen_fd,
-                             func_str, accept_sid, accept_sid, ep, flags);
              rv = ldp_fd_alloc ((u32) accept_sid);
              if (rv < 0)
                {
@@ -2975,32 +2799,16 @@ ldp_accept4 (int listen_fd, __SOCKADDR_ARG addr,
     }
   else
     {
-      func_str = "libc_accept4";
-
-      if (LDP_DEBUG > 0)
-       clib_warning ("LDP<%d>: listen fd %d (0x%x): calling %s(): "
-                     "addr %p, addr_len %p, flags 0x%x",
-                     getpid (), listen_fd, listen_fd, func_str,
-                     addr, addr_len, flags);
+      LDBG (0, "listen fd %d (0x%x): calling libc_accept4(): "
+           "addr %p, addr_len %p, flags 0x%x", listen_fd,
+           listen_fd, addr, addr_len, flags);
 
       rv = libc_accept4 (listen_fd, addr, addr_len, flags);
     }
 
-  if (LDP_DEBUG > 0)
-    {
-      if (rv < 0)
-       {
-         int errno_val = errno;
-         perror (func_str);
-         clib_warning ("LDP<%d>: ERROR: listen fd %d (0x%x): %s() failed! "
-                       "rv %d, errno = %d", getpid (), listen_fd,
-                       listen_fd, func_str, rv, errno_val);
-         errno = errno_val;
-       }
-      else
-       clib_warning ("LDP<%d>: listen fd %d (0x%x): returning %d (0x%x)",
-                     getpid (), listen_fd, listen_fd, rv, rv);
-    }
+  LDBG (1, "listen fd %d (0x%x): returning %d (0x%x)", listen_fd, listen_fd,
+       rv, rv);
+
   return rv;
 }
 
@@ -3076,12 +2884,12 @@ epoll_create1 (int flags)
       rv = libc_epoll_create1 (flags);
       ldp->vcl_needs_real_epoll = 0;
       ldpw->vcl_mq_epfd = rv;
-      LDBG (0, "LDP<%d>: created vcl epfd %u", getpid (), rv);
+      LDBG (0, "created vcl epfd %u", rv);
       return rv;
     }
   func_str = "vppcom_epoll_create";
 
-  LDBG (1, "LDP<%d>: calling %s()", getpid (), func_str);
+  LDBG (1, "calling %s()", func_str);
 
   rv = vppcom_epoll_create ();
 
@@ -3135,8 +2943,8 @@ epoll_ctl (int epfd, int op, int fd, struct epoll_event *event)
        */
       func_str = "libc_epoll_ctl";
 
-      LDBG (1, "LDP<%d>: epfd %d (0x%x): calling %s(): op %d, fd %d (0x%x),"
-           " event %p", getpid (), epfd, epfd, func_str, op, fd, fd, event);
+      LDBG (1, "epfd %d (0x%x): calling %s(): op %d, fd %d (0x%x),"
+           " event %p", epfd, epfd, func_str, op, fd, fd, event);
 
       rv = libc_epoll_ctl (epfd, op, fd, event);
       goto done;
@@ -3144,15 +2952,15 @@ epoll_ctl (int epfd, int op, int fd, struct epoll_event *event)
 
   sid = ldp_sid_from_fd (fd);
 
-  LDBG (0, "LDP<%d>: epfd %d (0x%x), vep_idx %d (0x%x), sid %d (0x%x)",
-       getpid (), epfd, epfd, vep_idx, vep_idx, sid, sid);
+  LDBG (0, "epfd %d (0x%x), vep_idx %d (0x%x), sid %d (0x%x)",
+       epfd, epfd, vep_idx, vep_idx, sid, sid);
 
   if (sid != INVALID_SESSION_ID)
     {
       func_str = "vppcom_epoll_ctl";
 
-      LDBG (1, "LDP<%d>: epfd %d (0x%x): calling %s(): vep_idx %d (0x%x),"
-           " op %d, sid %u (0x%x), event %p", getpid (), epfd, epfd,
+      LDBG (1, "epfd %d (0x%x): calling %s(): vep_idx %d (0x%x),"
+           " op %d, sid %u (0x%x), event %p", epfd, epfd,
            func_str, vep_idx, vep_idx, sid, sid, event);
 
       rv = vppcom_epoll_ctl (vep_idx, op, sid, event);
@@ -3170,16 +2978,16 @@ epoll_ctl (int epfd, int op, int fd, struct epoll_event *event)
       func_str = "vppcom_session_attr[GET_LIBC_EPFD]";
       libc_epfd = vppcom_session_attr (vep_idx, VPPCOM_ATTR_GET_LIBC_EPFD, 0,
                                       0);
-      LDBG (1, "LDP<%d>: epfd %d (0x%x), vep_idx %d (0x%x): %s() "
-           "returned libc_epfd %d (0x%x)", getpid (), epfd, epfd,
+      LDBG (1, "epfd %d (0x%x), vep_idx %d (0x%x): %s() "
+           "returned libc_epfd %d (0x%x)", epfd, epfd,
            vep_idx, vep_idx, func_str, libc_epfd, libc_epfd);
 
       if (!libc_epfd)
        {
          func_str = "libc_epoll_create1";
 
-         LDBG (1, "LDP<%d>: epfd %d (0x%x), vep_idx %d (0x%x): "
-               "calling %s(): EPOLL_CLOEXEC", getpid (), epfd, epfd,
+         LDBG (1, "epfd %d (0x%x), vep_idx %d (0x%x): "
+               "calling %s(): EPOLL_CLOEXEC", epfd, epfd,
                vep_idx, vep_idx, func_str);
 
          libc_epfd = libc_epoll_create1 (EPOLL_CLOEXEC);
@@ -3190,9 +2998,9 @@ epoll_ctl (int epfd, int op, int fd, struct epoll_event *event)
            }
 
          func_str = "vppcom_session_attr[SET_LIBC_EPFD]";
-         LDBG (1, "LDP<%d>: epfd %d (0x%x): calling %s(): vep_idx %d (0x%x),"
+         LDBG (1, "epfd %d (0x%x): calling %s(): vep_idx %d (0x%x),"
                " VPPCOM_ATTR_SET_LIBC_EPFD, libc_epfd %d (0x%x), size %d",
-               getpid (), epfd, epfd, func_str, vep_idx, vep_idx, libc_epfd,
+               epfd, epfd, func_str, vep_idx, vep_idx, libc_epfd,
                libc_epfd, size);
 
          rv = vppcom_session_attr (vep_idx, VPPCOM_ATTR_SET_LIBC_EPFD,
@@ -3213,8 +3021,8 @@ epoll_ctl (int epfd, int op, int fd, struct epoll_event *event)
 
       func_str = "libc_epoll_ctl";
 
-      LDBG (1, "LDP<%d>: epfd %d (0x%x): calling %s(): libc_epfd %d (0x%x), "
-           "op %d, fd %d (0x%x), event %p", getpid (), epfd, epfd, func_str,
+      LDBG (1, "epfd %d (0x%x): calling %s(): libc_epfd %d (0x%x), "
+           "op %d, fd %d (0x%x), event %p", epfd, epfd, func_str,
            libc_epfd, libc_epfd, op, fd, fd, event);
 
       rv = libc_epoll_ctl (libc_epfd, op, fd, event);
@@ -3281,9 +3089,9 @@ ldp_epoll_pwait (int epfd, struct epoll_event *events, int maxevents,
       goto done;
     }
 
-  LDBG (2, "LDP<%d>: epfd %d (0x%x): vep_idx %d (0x%x), libc_epfd %d (0x%x), "
+  LDBG (2, "epfd %d (0x%x): vep_idx %d (0x%x), libc_epfd %d (0x%x), "
        "events %p, maxevents %d, timeout %d, sigmask %p: time_to_wait %.02f",
-       getpid (), epfd, epfd, vep_idx, vep_idx, libc_epfd, libc_epfd, events,
+       epfd, epfd, vep_idx, vep_idx, libc_epfd, libc_epfd, events,
        maxevents, timeout, sigmask, time_to_wait, time_out);
   do
     {
@@ -3291,8 +3099,8 @@ ldp_epoll_pwait (int epfd, struct epoll_event *events, int maxevents,
        {
          func_str = "vppcom_epoll_wait";
 
-         LDBG (3, "LDP<%d>: epfd %d (0x%x): calling %s(): vep_idx %d (0x%x),"
-               " events %p, maxevents %d", getpid (), epfd, epfd, func_str,
+         LDBG (3, "epfd %d (0x%x): calling %s(): vep_idx %d (0x%x),"
+               " events %p, maxevents %d", epfd, epfd, func_str,
                vep_idx, vep_idx, events, maxevents);
 
          rv = vppcom_epoll_wait (vep_idx, events, maxevents, 0);
@@ -3315,8 +3123,8 @@ ldp_epoll_pwait (int epfd, struct epoll_event *events, int maxevents,
        {
          func_str = "libc_epoll_pwait";
 
-         LDBG (3, "LDP<%d>: epfd %d (0x%x): calling %s(): libc_epfd %d "
-               "(0x%x), events %p, maxevents %d, sigmask %p", getpid (),
+         LDBG (3, "epfd %d (0x%x): calling %s(): libc_epfd %d "
+               "(0x%x), events %p, maxevents %d, sigmask %p",
                epfd, epfd, func_str, libc_epfd, libc_epfd, events,
                maxevents, sigmask);
 
@@ -3374,8 +3182,7 @@ poll (struct pollfd *fds, nfds_t nfds, int timeout)
   vcl_poll_t *vp;
   double wait_for_time;
 
-  LDBG (3, "LDP<%d>: fds %p, nfds %d, timeout %d", getpid (), fds, nfds,
-       timeout);
+  LDBG (3, "fds %p, nfds %d, timeout %d", fds, nfds, timeout);
 
   if (timeout >= 0)
     wait_for_time = (f64) timeout / 1000;
@@ -3387,9 +3194,8 @@ poll (struct pollfd *fds, nfds_t nfds, int timeout)
       if (fds[i].fd < 0)
        continue;
 
-      LDBG (3, "LDP<%d>: fds[%d] fd %d (0x%0x) events = 0x%x revents = 0x%x",
-           getpid (), i, fds[i].fd, fds[i].fd, fds[i].events,
-           fds[i].revents);
+      LDBG (3, "fds[%d] fd %d (0x%0x) events = 0x%x revents = 0x%x",
+           i, fds[i].fd, fds[i].fd, fds[i].events, fds[i].revents);
 
       sid = ldp_sid_from_fd (fds[i].fd);
       if (sid != INVALID_SESSION_ID)
@@ -3420,8 +3226,8 @@ poll (struct pollfd *fds, nfds_t nfds, int timeout)
        {
          func_str = "vppcom_poll";
 
-         LDBG (3, "LDP<%d>: calling %s(): vcl_poll %p, n_sids %u (0x%x): "
-               "n_libc_fds %u", getpid (), func_str, ldpw->vcl_poll,
+         LDBG (3, "calling %s(): vcl_poll %p, n_sids %u (0x%x): "
+               "n_libc_fds %u", func_str, ldpw->vcl_poll,
                vec_len (ldpw->vcl_poll), vec_len (ldpw->vcl_poll),
                vec_len (ldpw->libc_poll));
 
@@ -3440,8 +3246,8 @@ poll (struct pollfd *fds, nfds_t nfds, int timeout)
        {
          func_str = "libc_poll";
 
-         LDBG (3, "LDP<%d>: calling %s(): fds %p, nfds %u: n_sids %u",
-               getpid (), fds, nfds, vec_len (ldpw->vcl_poll));
+         LDBG (3, "calling %s(): fds %p, nfds %u: n_sids %u",
+               fds, nfds, vec_len (ldpw->vcl_poll));
 
          rv = libc_poll (ldpw->libc_poll, vec_len (ldpw->libc_poll), 0);
          if (rv < 0)

diff --git a/src/vcl/vppcom.c b/src/vcl/vppcom.c
index 9bb6a98..88a67dd 100644 (file)
--- a/src/vcl/vppcom.c
+++ b/src/vcl/vppcom.c
@@ -464,8 +464,7 @@ vcl_session_bound_handler (vcl_worker_t * wrk, session_bound_msg_t * mp)
       session->tx_fifo = tx_fifo;
     }
 
-  VDBG (0, "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;
 }
 
@@ -569,7 +568,7 @@ vppcom_wait_for_session_state_change (u32 session_index,
     }
   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);
 
@@ -1003,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)
@@ -1077,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);
 
@@ -1138,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
@@ -1173,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;
     }
 
@@ -1271,7 +1262,7 @@ handle:
     VCL_SESS_ATTR_SET (client_session->attr, VCL_SESS_ATTR_NONBLOCK);
 
   listen_vpp_handle = listen_session->vpp_handle;
-  VDBG (0, "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",
        listen_vpp_handle, listen_session_handle,
        client_session->vpp_handle, client_session_index,
@@ -1299,16 +1290,12 @@ handle:
   vcl_send_session_accepted_reply (vpp_evt_q, client_session->client_context,
                                   client_session->vpp_handle, 0);
 
-  VDBG (0, "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", 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));