2007-07-17 Marcus Brinkmann <marcus@g10code.de>
[gpgme.git] / gpgme / posix-io.c
index c44879d..ca77cf4 100644 (file)
@@ -1,6 +1,6 @@
 /* posix-io.c - Posix I/O functions
    Copyright (C) 2000 Werner Koch (dd9jn)
-   Copyright (C) 2001, 2002, 2004, 2005 g10 Code GmbH
+   Copyright (C) 2001, 2002, 2004, 2005, 2007 g10 Code GmbH
 
    This file is part of GPGME.
  
@@ -33,6 +33,7 @@
 #include <sys/time.h>
 #include <sys/types.h>
 #include <sys/wait.h>
+#include <ctype.h>
 
 #include "util.h"
 #include "priv-io.h"
@@ -73,44 +74,40 @@ static struct
   void *value;
 } notify_table[256];
 
+
 int
 _gpgme_io_read (int fd, void *buffer, size_t count)
 {
   int nread;
-  int saved_errno;
+  TRACE_BEG2 (DEBUG_SYSIO, "_gpgme_io_read", fd,
+             "buffer=%p, count=%u", buffer, count);
 
-  DEBUG2 ("fd %d: about to read %d bytes\n", fd, (int) count);
   do
     {
       nread = _gpgme_ath_read (fd, buffer, count);
     }
   while (nread == -1 && errno == EINTR);
-  saved_errno = errno;
-  DEBUG2 ("fd %d: got %d bytes\n", fd, nread);
-  if (nread > 0)
-    _gpgme_debug (2, "fd %d: got `%.*s'\n", fd, nread, buffer);
-  errno = saved_errno;
-  return nread;
+
+  TRACE_LOGBUF (buffer, nread);
+  return TRACE_SYSRES (nread);
 }
 
 
 int
 _gpgme_io_write (int fd, const void *buffer, size_t count)
 {
-  int saved_errno;
   int nwritten;
+  TRACE_BEG2 (DEBUG_SYSIO, "_gpgme_io_write", fd,
+             "buffer=%p, count=%u", buffer, count);
+  TRACE_LOGBUF (buffer, count);
 
-  DEBUG2 ("fd %d: about to write %d bytes\n", fd, (int) count);
-  _gpgme_debug (2, "fd %d: write `%.*s'\n", fd, (int) count, buffer);
   do
     {
       nwritten = _gpgme_ath_write (fd, buffer, count);
     }
   while (nwritten == -1 && errno == EINTR);
-  saved_errno = errno;
-  DEBUG2 ("fd %d:          wrote %d bytes\n", fd, (int) nwritten);
-  errno = saved_errno;
-  return nwritten;
+
+  return TRACE_SYSRES (nwritten);
 }
 
 
@@ -119,10 +116,14 @@ _gpgme_io_pipe (int filedes[2], int inherit_idx)
 {
   int saved_errno;
   int err;
+  TRACE_BEG2 (DEBUG_SYSIO, "_gpgme_io_pipe", filedes,
+             "inherit_idx=%i (GPGME uses it for %s)",
+             inherit_idx, inherit_idx ? "writing" : "reading");
 
   err = pipe (filedes);
   if (err < 0)
-    return err;
+    return TRACE_SYSRES (err);
+
   /* FIXME: Should get the old flags first.  */
   err = fcntl (filedes[1 - inherit_idx], F_SETFD, FD_CLOEXEC);
   saved_errno = errno;
@@ -132,28 +133,41 @@ _gpgme_io_pipe (int filedes[2], int inherit_idx)
       close (filedes[1]);
     }
   errno = saved_errno;
-  return err;
+  if (err)
+    return TRACE_SYSRES (err);
+
+  return TRACE_SUC2 ("read=0x%x, write=0x%x", filedes[0], filedes[1]);
 }
 
 
 int
 _gpgme_io_close (int fd)
 {
+  int res;
+
+  TRACE_BEG (DEBUG_SYSIO, "_gpgme_io_close", fd);
+
   if (fd == -1)
-    return -1;
+    {
+      errno = EINVAL;
+      return TRACE_SYSRES (-1);
+    }
+
   /* First call the notify handler.  */
-  DEBUG1 ("closing fd %d", fd);
   if (fd >= 0 && fd < (int) DIM (notify_table))
     {
       if (notify_table[fd].handler)
        {
+         TRACE_LOG2 ("invoking close handler %p/%p",
+                     notify_table[fd].handler, notify_table[fd].value);
          notify_table[fd].handler (fd, notify_table[fd].value);
          notify_table[fd].handler = NULL;
          notify_table[fd].value = NULL;
         }
     }
   /* Then do the close.  */    
-  return close (fd);
+  res = close (fd);
+  return TRACE_SYSRES (res);
 }
 
 
@@ -161,14 +175,19 @@ int
 _gpgme_io_set_close_notify (int fd, _gpgme_close_notify_handler_t handler,
                            void *value)
 {
+  TRACE_BEG2 (DEBUG_SYSIO, "_gpgme_io_set_close_notify", fd,
+             "close_handler=%p/%p", handler, value);
+
   assert (fd != -1);
 
   if (fd < 0 || fd >= (int) DIM (notify_table))
-    return -1;
-  DEBUG1 ("set notification for fd %d", fd);
+    {
+      errno = EINVAL;
+      return TRACE_SYSRES (-1);
+    }
   notify_table[fd].handler = handler;
   notify_table[fd].value = value;
-  return 0;
+  return TRACE_SYSRES (0);
 }
 
 
@@ -176,12 +195,15 @@ int
 _gpgme_io_set_nonblocking (int fd)
 {
   int flags;
+  int res;
+  TRACE_BEG (DEBUG_SYSIO, "_gpgme_io_set_nonblocking", fd);
 
   flags = fcntl (fd, F_GETFL, 0);
   if (flags == -1)
-    return -1;
+    return TRACE_SYSRES (-1);
   flags |= O_NONBLOCK;
-  return fcntl (fd, F_SETFL, flags);
+  res = fcntl (fd, F_SETFL, flags);
+  return TRACE_SYSRES (res);
 }
 
 
@@ -217,12 +239,21 @@ _gpgme_io_spawn (const char *path, char **argv,
 {
   pid_t pid;
   int i;
-  int status, signo;
-
+  int status;
+  int signo;
+  TRACE_BEG1 (DEBUG_SYSIO, "_gpgme_io_spawn", path,
+             "path=%s", path);
+  i = 0;
+  while (argv[i])
+    {
+      TRACE_LOG2 ("argv[%2i] = %s", i, argv[i]);
+      i++;
+    }
+  
   pid = fork ();
   if (pid == -1) 
-    return -1;
-
+    return TRACE_SYSRES (-1);
+  
   if (!pid)
     {
       /* Intermediate child to prevent zombie processes.  */
@@ -245,7 +276,12 @@ _gpgme_io_spawn (const char *path, char **argv,
                  if (dup2 (fd_child_list[i].fd,
                            fd_child_list[i].dup_to) == -1)
                    {
-                     DEBUG1 ("dup2 failed in child: %s\n", strerror (errno));
+#if 0
+                     /* FIXME: The debug file descriptor is not
+                        dup'ed anyway, so we can't see this.  */
+                     TRACE_LOG1 ("dup2 failed in child: %s\n",
+                                 strerror (errno));
+#endif
                      _exit (8);
                    }
                  if (fd_child_list[i].dup_to == 0)
@@ -261,7 +297,12 @@ _gpgme_io_spawn (const char *path, char **argv,
              int fd = open ("/dev/null", O_RDWR);
              if (fd == -1)
                {
-                 DEBUG1 ("can't open `/dev/null': %s\n", strerror (errno));
+#if 0
+                 /* FIXME: The debug file descriptor is not dup'ed
+                    anyway, so we can't see this.  */
+                 TRACE_LOG1 ("can't open `/dev/null': %s\n",
+                             strerror (errno));
+#endif
                  _exit (8);
                }
              /* Make sure that the process has a connected stdin.  */
@@ -269,16 +310,24 @@ _gpgme_io_spawn (const char *path, char **argv,
                {
                  if (dup2 (fd, 0) == -1)
                    {
-                     DEBUG1("dup2(/dev/null, 0) failed: %s\n",
-                            strerror (errno));
+#if 0
+                 /* FIXME: The debug file descriptor is not dup'ed
+                    anyway, so we can't see this.  */
+                     TRACE_LOG1 ("dup2(/dev/null, 0) failed: %s\n",
+                                 strerror (errno));
+#endif
                      _exit (8);
                    }
                }
              if (!duped_stderr)
                if (dup2 (fd, 2) == -1)
                  {
-                   DEBUG1 ("dup2(dev/null, 2) failed: %s\n",
-                           strerror (errno));
+#if 0
+                   /* FIXME: The debug file descriptor is not dup'ed
+                      anyway, so we can't see this.  */
+                   TRACE_LOG1 ("dup2(dev/null, 2) failed: %s\n",
+                               strerror (errno));
+#endif
                    _exit (8);
                  }
              close (fd);
@@ -287,7 +336,11 @@ _gpgme_io_spawn (const char *path, char **argv,
          execv ( path, argv );
          /* Hmm: in that case we could write a special status code to the
             status-pipe.  */
-         DEBUG1 ("exec of `%s' failed\n", path);
+#if 0
+         /* FIXME: The debug file descriptor is not dup'ed anyway, so
+            we can't see this.  */
+         TRACE_LOG1 ("exec of `%s' failed\n", path);
+#endif
          _exit (8);
        } /* End child.  */
       if (pid == -1)
@@ -295,34 +348,37 @@ _gpgme_io_spawn (const char *path, char **argv,
       else
        _exit (0);
     }
-    
+
+  TRACE_LOG1 ("waiting for child process pid=%i", pid);
   _gpgme_io_waitpid (pid, 1, &status, &signo);
   if (status)
-    return -1;
+    return TRACE_SYSRES (-1);
 
   /* .dup_to is not used in the parent list.  */
   for (i = 0; fd_parent_list[i].fd != -1; i++)
     _gpgme_io_close (fd_parent_list[i].fd);
 
-  return 0;
+  return TRACE_SYSRES (0);
 }
 
 
-/*
- * Select on the list of fds.
- * Returns: -1 = error
- *           0 = timeout or nothing to select
- *          >0 = number of signaled fds
- */
+/* Select on the list of fds.  Returns: -1 = error, 0 = timeout or
+   nothing to select, > 0 = number of signaled fds.  */
 int
 _gpgme_io_select (struct io_select_fd_s *fds, size_t nfds, int nonblock)
 {
   fd_set readfds;
   fd_set writefds;
   unsigned int i;
-  int any, max_fd, n, count;
-  struct timeval timeout = { 1, 0 }; /* Use a 1s timeout.  */
+  int any;
+  int max_fd;
+  int n;
+  int count;
+  /* Use a 1s timeout.  */
+  struct timeval timeout = { 1, 0 };
   void *dbg_help = NULL;
+  TRACE_BEG2 (DEBUG_SYSIO, "_gpgme_io_select", fds,
+             "nfds=%u, nonblock=%u", nfds, nonblock);
 
   FD_ZERO (&readfds);
   FD_ZERO (&writefds);
@@ -330,21 +386,22 @@ _gpgme_io_select (struct io_select_fd_s *fds, size_t nfds, int nonblock)
   if (nonblock)
     timeout.tv_sec = 0;
 
-  DEBUG_BEGIN (dbg_help, 3, "gpgme:select on [ ");
+  TRACE_SEQ (dbg_help, "select on [ ");
+
   any = 0;
   for (i = 0; i < nfds; i++)
     {
       if (fds[i].fd == -1) 
        continue;
       if (fds[i].frozen)
-       DEBUG_ADD1 (dbg_help, "f%d ", fds[i].fd);
+       TRACE_ADD1 (dbg_help, "f0x%x ", fds[i].fd);
       else if (fds[i].for_read)
        {
          assert (!FD_ISSET (fds[i].fd, &readfds));
          FD_SET (fds[i].fd, &readfds);
          if (fds[i].fd > max_fd)
            max_fd = fds[i].fd;
-         DEBUG_ADD1 (dbg_help, "r%d ", fds[i].fd);
+         TRACE_ADD1 (dbg_help, "r0x%x ", fds[i].fd);
          any = 1;
         }
       else if (fds[i].for_write)
@@ -353,14 +410,14 @@ _gpgme_io_select (struct io_select_fd_s *fds, size_t nfds, int nonblock)
          FD_SET (fds[i].fd, &writefds);
          if (fds[i].fd > max_fd)
            max_fd = fds[i].fd;
-         DEBUG_ADD1 (dbg_help, "w%d ", fds[i].fd);
+         TRACE_ADD1 (dbg_help, "w0x%x ", fds[i].fd);
          any = 1;
         }
       fds[i].signaled = 0;
     }
-  DEBUG_END (dbg_help, "]"); 
+  TRACE_END (dbg_help, "]"); 
   if (!any)
-    return 0;
+    return TRACE_SYSRES (0);
 
   do
     {
@@ -369,27 +426,22 @@ _gpgme_io_select (struct io_select_fd_s *fds, size_t nfds, int nonblock)
     }
   while (count < 0 && errno == EINTR);
   if (count < 0)
-    {
-      int saved_errno = errno;
-      DEBUG1 ("_gpgme_io_select failed: %s\n", strerror (errno));
-      errno = saved_errno;
-      return -1; /* error */
-    }
+    return TRACE_SYSRES (-1);
 
-  DEBUG_BEGIN (dbg_help, 3, "select OK [ ");
-  if (DEBUG_ENABLED (dbg_help))
+  TRACE_SEQ (dbg_help, "select OK [ ");
+  if (TRACE_ENABLED (dbg_help))
     {
       for (i = 0; i <= max_fd; i++)
        {
          if (FD_ISSET (i, &readfds))
-           DEBUG_ADD1 (dbg_help, "r%d ", i);
+           TRACE_ADD1 (dbg_help, "r0x%x ", i);
          if (FD_ISSET (i, &writefds))
-           DEBUG_ADD1 (dbg_help, "w%d ", i);
+           TRACE_ADD1 (dbg_help, "w0x%x ", i);
         }
-      DEBUG_END (dbg_help, "]");
+      TRACE_END (dbg_help, "]");
     }
     
-  /* n is used to optimize it a little bit.  */
+  /* The variable N is used to optimize it a little bit.  */
   for (n = count, i = 0; i < nfds && n; i++)
     {
       if (fds[i].fd == -1)
@@ -411,7 +463,7 @@ _gpgme_io_select (struct io_select_fd_s *fds, size_t nfds, int nonblock)
             }
         }
     }
-  return count;
+  return TRACE_SYSRES (count);
 }
 
 \f
@@ -421,6 +473,8 @@ _gpgme_io_recvmsg (int fd, struct msghdr *msg, int flags)
   int nread;
   int saved_errno;
   struct iovec *iov;
+  TRACE_BEG2 (DEBUG_SYSIO, "_gpgme_io_recvmsg", fd,
+             "msg=%p, flags=%i", msg, flags);
 
   nread = 0;
   iov = msg->msg_iov;
@@ -430,15 +484,14 @@ _gpgme_io_recvmsg (int fd, struct msghdr *msg, int flags)
       iov++;
     }
   
-  DEBUG2 ("fd %d: about to receive %d bytes\n",
-         fd, (int) nread);
+  TRACE_LOG1 ("about to receive %d bytes", nread);
+
   do
     {
       nread = _gpgme_ath_recvmsg (fd, msg, flags);
     }
   while (nread == -1 && errno == EINTR);
   saved_errno = errno;
-  DEBUG2 ("fd %d: got %d bytes\n", fd, nread);
   if (nread > 0)
     {
       int nr = nread;
@@ -447,23 +500,23 @@ _gpgme_io_recvmsg (int fd, struct msghdr *msg, int flags)
       while (nr > 0)
        {
          int len = nr > iov->iov_len ? iov->iov_len : nr;
-         _gpgme_debug (2, "fd %d: got `%.*s'\n", fd, len,
-                       msg->msg_iov->iov_base);
+         TRACE_LOGBUF (msg->msg_iov->iov_base, len);
          iov++;
          nr -= len;
        }
     }
   errno = saved_errno;
-  return nread;
+  return TRACE_SYSRES (nread);
 }
 
 
 int
 _gpgme_io_sendmsg (int fd, const struct msghdr *msg, int flags)
 {
-  int saved_errno;
   int nwritten;
   struct iovec *iov;
+  TRACE_BEG2 (DEBUG_SYSIO, "_gpgme_io_sendmsg", fd,
+             "msg=%p, flags=%i", msg, flags);
 
   nwritten = 0;
   iov = msg->msg_iov;
@@ -473,13 +526,12 @@ _gpgme_io_sendmsg (int fd, const struct msghdr *msg, int flags)
       iov++;
     }
 
-  DEBUG2 ("fd %d: about to write %d bytes\n", fd, (int) nwritten);
+  TRACE_LOG1 ("about to receive %d bytes", nwritten);
   iov = msg->msg_iov;
   while (nwritten > 0)
     {
       int len = nwritten > iov->iov_len ? iov->iov_len : nwritten;
-      _gpgme_debug (2, "fd %d: write `%.*s'\n", fd, len,
-                   msg->msg_iov->iov_base);
+      TRACE_LOGBUF (msg->msg_iov->iov_base, len);
       iov++;
       nwritten -= len;
     }
@@ -489,10 +541,7 @@ _gpgme_io_sendmsg (int fd, const struct msghdr *msg, int flags)
       nwritten = _gpgme_ath_sendmsg (fd, msg, flags);
     }
   while (nwritten == -1 && errno == EINTR);
-  saved_errno = errno;
-  DEBUG2 ("fd %d:          wrote %d bytes\n", fd, (int) nwritten);
-  errno = saved_errno;
-  return nwritten;
+  return TRACE_SYSRES (nwritten);
 }