Improve tracing of estream.

* src/gpgrt-int.h (trace_errno): Add new parameter.  Adjust all users.
* src/init.c (trace_fp, trace_with_errno, trace_missing_lf)
(trace_prefix_done): New vars.
(_gpgrt_internal_trace_begin): Add arg WITH_ERRNO.  Open a trace file
on first use.  Init new vars.
(print_internal_trace_prefix): New.
* src/estream.c, src/w32-estream.c: Improve tracing.

Signed-off-by: Werner Koch <[email protected]>

4 files changed, 191 insertions, 94 deletions

diff --git a/src/estream.c b/src/estream.c
index ee3a7df..9f227a6 100644
--- a/src/estream.c
+++ b/src/estream.c
@@ -913,7 +913,7 @@ func_fd_create (void **cookie, int fd, unsigned int modeflags, int no_close)
   estream_cookie_fd_t fd_cookie;
   int err;
 
-  trace (("enter: fd=%d mf=%u nc=%d", fd, modeflags, no_close));
+  trace (("enter: fd=%d mf=%x nc=%d", fd, modeflags, no_close));
 
   fd_cookie = mem_alloc (sizeof (*fd_cookie));
   if (! fd_cookie)
@@ -932,7 +932,7 @@ func_fd_create (void **cookie, int fd, unsigned int modeflags, int no_close)
       err = 0;
     }
 
-  trace_errno (("leave: cookie=%p err=%d", *cookie, err));
+  trace_errno (err, ("leave: cookie=%p err=%d", *cookie, err));
   return err;
 }
 
@@ -969,7 +969,7 @@ func_fd_read (void *cookie, void *buffer, size_t size)
         post_syscall_func ();
     }
 
-  trace_errno (("leave: bytes_read=%d", (int)bytes_read));
+  trace_errno (bytes_read == -1, ("leave: bytes_read=%d", (int)bytes_read));
   return bytes_read;
 }
 
@@ -1005,7 +1005,8 @@ func_fd_write (void *cookie, const void *buffer, size_t size)
   else
     bytes_written = size; /* Note that for a flush SIZE should be 0.  */
 
-  trace_errno (("leave: bytes_written=%d", (int)bytes_written));
+  trace_errno (bytes_written == -1,
+               ("leave: bytes_written=%d", (int)bytes_written));
   return bytes_written;
 }
 
@@ -1110,7 +1111,7 @@ func_fd_destroy (void *cookie)
   else
     err = 0;
 
-  trace_errno (("leave: err=%d", err));
+  trace_errno (err,("leave: err=%d", err));
   return err;
 }
 
@@ -1156,7 +1157,7 @@ func_w32_create (void **cookie, HANDLE hd,
   estream_cookie_w32_t w32_cookie;
   int err;
 
-  trace (("enter: hd=%p mf=%u nc=%d nsc=%d",
+  trace (("enter: hd=%p mf=%x nc=%d nsc=%d",
           hd, modeflags, no_close, no_syscall_clamp));
   w32_cookie = mem_alloc (sizeof (*w32_cookie));
   if (!w32_cookie)
@@ -1175,7 +1176,7 @@ func_w32_create (void **cookie, HANDLE hd,
       err = 0;
     }
 
-  trace_errno (("leave: cookie=%p err=%d", *cookie, err));
+  trace_errno (err, ("leave: cookie=%p err=%d", *cookie, err));
   return err;
 }
 
@@ -1208,9 +1209,11 @@ func_w32_read (void *cookie, void *buffer, size_t size)
         {
           DWORD nread, ec;
 
+          trace (("cookie=%p calling ReadFile", cookie));
           if (!ReadFile (w32_cookie->hd, buffer, size, &nread, NULL))
             {
               ec = GetLastError ();
+              trace (("cookie=%p ReadFile failed: ec=%ld", cookie,ec));
               if (ec == ERROR_BROKEN_PIPE)
                 bytes_read = 0; /* Like our pth_read we handle this as EOF.  */
               else
@@ -1227,7 +1230,7 @@ func_w32_read (void *cookie, void *buffer, size_t size)
         post_syscall_func ();
     }
 
-  trace_errno (("leave: bytes_read=%d", (int)bytes_read));
+  trace_errno (bytes_read==-1,("leave: bytes_read=%d", (int)bytes_read));
   return bytes_read;
 }
 
@@ -1259,9 +1262,12 @@ func_w32_write (void *cookie, const void *buffer, size_t size)
         {
           DWORD nwritten;
 
+          trace (("cookie=%p calling WriteFile", cookie));
 	  if (!WriteFile (w32_cookie->hd, buffer, size, &nwritten, NULL))
 	    {
-	      _set_errno (map_w32_to_errno (GetLastError ()));
+              DWORD ec = GetLastError ();
+              trace (("cookie=%p WriteFile failed: ec=%ld", cookie, ec));
+	      _set_errno (map_w32_to_errno (ec));
 	      bytes_written = -1;
 	    }
 	  else
@@ -1274,8 +1280,8 @@ func_w32_write (void *cookie, const void *buffer, size_t size)
   else
     bytes_written = size; /* Note that for a flush SIZE should be 0.  */
 
-  trace_errno (("leave: bytes_written=%d", (int)bytes_written));
-
+  trace_errno (bytes_written==-1,
+               ("leave: bytes_written=%d", (int)bytes_written));
   return bytes_written;
 }
 
@@ -1356,9 +1362,12 @@ func_w32_destroy (void *cookie)
         err = 0;
       else
         {
+          trace (("cookie=%p closing handle %p", cookie, w32_cookie->hd));
           if (!CloseHandle (w32_cookie->hd))
             {
-	      _set_errno (map_w32_to_errno (GetLastError ()));
+              DWORD ec = GetLastError ();
+              trace (("cookie=%p CloseHandle failed: ec=%ld", cookie,ec));
+	      _set_errno (map_w32_to_errno (ec));
               err = -1;
             }
           else
@@ -1369,7 +1378,7 @@ func_w32_destroy (void *cookie)
   else
     err = 0;
 
-  trace_errno (("leave: err=%d", err));
+  trace_errno (err, ("leave: err=%d", err));
   return err;
 }
 
@@ -2059,6 +2068,7 @@ deinit_stream_obj (estream_t stream)
   gpgrt_cookie_close_function_t func_close;
   int err, tmp_err;
 
+  trace (("enter: stream %p", stream));
   func_close = stream->intern->func_close;
 
   err = 0;
@@ -2070,6 +2080,7 @@ deinit_stream_obj (estream_t stream)
     }
   if (func_close)
     {
+      trace (("stream %p calling func_close", stream));
       tmp_err = func_close (stream->intern->cookie);
       if (!err)
         err = tmp_err;
@@ -2085,6 +2096,7 @@ deinit_stream_obj (estream_t stream)
       stream->intern->onclose = tmp;
     }
 
+  trace_errno (err, ("leave: stream %p err=%d", stream, err));
   return err;
 }
 
@@ -2103,6 +2115,9 @@ create_stream (estream_t *r_stream, void *cookie, es_syshd_t *syshd,
   estream_internal_t stream_internal_new;
   estream_t stream_new;
   int err;
+#if HAVE_W32_SYSTEM
+  void *old_cookie = NULL;
+#endif
 
   stream_new = NULL;
   stream_internal_new = NULL;
@@ -2151,6 +2166,7 @@ create_stream (estream_t *r_stream, void *cookie, es_syshd_t *syshd,
         goto out;
 
       modeflags &= ~O_NONBLOCK;
+      old_cookie = cookie;
       cookie = new_cookie;
       kind = BACKEND_W32_POLLABLE;
       functions = _gpgrt_functions_w32_pollable;
@@ -2171,6 +2187,7 @@ create_stream (estream_t *r_stream, void *cookie, es_syshd_t *syshd,
 
   if (err)
     {
+      trace_errno (err, ("leave: err=%d", err));
       if (stream_new)
 	{
 	  deinit_stream_obj (stream_new);
@@ -2179,6 +2196,13 @@ create_stream (estream_t *r_stream, void *cookie, es_syshd_t *syshd,
 	  mem_free (stream_new);
 	}
     }
+#if HAVE_W32_SYSTEM
+  else if (old_cookie)
+    trace (("leave: success stream=%p cookie=%p,%p",
+            *r_stream, old_cookie, cookie));
+#endif
+  else
+    trace (("leave: success stream=%p cookie=%p", *r_stream, cookie));
 
   return err;
 }
@@ -2215,7 +2239,7 @@ do_close (estream_t stream, int with_locked_list)
   else
     err = 0;
 
-  trace_errno (("stream %p err=%d", stream, err));
+  trace_errno (err, ("stream %p err=%d", stream, err));
   return err;
 }
 
@@ -4893,7 +4917,7 @@ _gpgrt_poll (gpgrt_poll_t *fds, unsigned int nfds, int timeout)
 
   if (ret == -1)
     {
-      trace_errno (("select failed: "));
+      trace_errno (1, ("select failed: "));
       count = -1;
       goto leave;
     }
diff --git a/src/gpgrt-int.h b/src/gpgrt-int.h
index e1cf50b..701e1d4 100644
--- a/src/gpgrt-int.h
+++ b/src/gpgrt-int.h
@@ -51,31 +51,33 @@ gpg_err_code_t _gpgrt_yield (void);
 
 /* Trace support.  */
 
-void _gpgrt_internal_trace_begin (const char *mod, const char *file, int line);
-void _gpgrt_internal_trace (const char *format,
-                            ...) GPGRT_ATTR_PRINTF(1,2);
-void _gpgrt_internal_trace_errno (const char *format,
-                                  ...) GPGRT_ATTR_PRINTF(1,2);
-void _gpgrt_internal_trace_printf (const char *format,
-                                   ...) GPGRT_ATTR_PRINTF(1,2);
-void _gpgrt_internal_trace_end (void);
-
+/* The trace macro is used this way:
+ *   trace (("enter - foo=%d bar=%s", foo, bar));
+ * Note the double parenthesis, they are important.
+ * To append the current errno to the output, use
+ *   trace_errno (EXTPR,("leave - baz=%d", faz));
+ * If EXPR evaluates to true the output of strerror (errno)
+ * is appended to the output.  Note that the trace function does
+ * not modify ERRNO.  To enable tracing you need to have this
+ *  #define ENABLE_TRACING "modulename"
+ * before you include gpgrt-int.h.
+ */
 #ifdef ENABLE_TRACING
 # define trace(X) do { \
                        _gpgrt_internal_trace_begin \
-                           (ENABLE_TRACING, __func__, __LINE__); \
+                         (ENABLE_TRACING, __func__, __LINE__, 0); \
                        _gpgrt_internal_trace X; \
                        _gpgrt_internal_trace_end (); \
                      } while (0)
-# define trace_errno(X) do { \
+# define trace_errno(C,X) do {                     \
                        _gpgrt_internal_trace_begin \
-                           (ENABLE_TRACING, __func__, __LINE__); \
-                       _gpgrt_internal_trace_errno X; \
+                         (ENABLE_TRACING, __func__, __LINE__, (C)); \
+                       _gpgrt_internal_trace X;      \
                        _gpgrt_internal_trace_end (); \
                      } while (0)
 # define trace_start(X) do { \
                        _gpgrt_internal_trace_begin \
-                           (ENABLE_TRACING, __func__, __LINE__); \
+                         (ENABLE_TRACING, __func__, __LINE__, 0); \
                        _gpgrt_internal_trace_printf X; \
                      } while (0)
 # define trace_append(X) do { \
@@ -87,12 +89,21 @@ void _gpgrt_internal_trace_end (void);
                      } while (0)
 #else
 # define trace(X) do { } while (0)
-# define trace_errno(X) do { } while (0)
+# define trace_errno(C,X) do { } while (0)
 # define trace_start(X) do { } while (0)
 # define trace_append(X) do { } while (0)
 # define trace_finish(X) do { } while (0)
 #endif /*!ENABLE_TRACING*/
 
+void _gpgrt_internal_trace_begin (const char *mod, const char *file, int line,
+                                  int with_errno);
+void _gpgrt_internal_trace (const char *format,
+                            ...) GPGRT_ATTR_PRINTF(1,2);
+void _gpgrt_internal_trace_printf (const char *format,
+                                   ...) GPGRT_ATTR_PRINTF(1,2);
+void _gpgrt_internal_trace_end (void);
+
+
 
 /* Local definitions for estream.  */
 
diff --git a/src/init.c b/src/init.c
index e90bec5..a1ee505 100644
--- a/src/init.c
+++ b/src/init.c
@@ -214,67 +214,88 @@ _gpg_err_set_errno (int err)
 
 
 
-/* Internal tracing functions.  We use flockfile and funlockfile to
- * protect their use. */
+/* Internal tracing functions.  Except for TARCE_FP we use flockfile
+ * and funlockfile to protect their use. */
+static FILE *trace_fp;
 static int trace_save_errno;
+static int trace_with_errno;
 static const char *trace_arg_module;
 static const char *trace_arg_file;
 static int trace_arg_line;
+static int trace_missing_lf;
+static int trace_prefix_done;
 
 void
-_gpgrt_internal_trace_begin (const char *module, const char *file, int line)
+_gpgrt_internal_trace_begin (const char *module, const char *file, int line,
+                             int with_errno)
 {
   int save_errno = errno;
+
+  if (!trace_fp)
+    {
+      FILE *fp;
+      const char *s = getenv ("GPGRT_TRACE_FILE");
+
+      if (!s || !(fp = fopen (s, "wb")))
+        fp = stderr;
+      trace_fp = fp;
+    }
+
 #ifdef HAVE_FLOCKFILE
-  flockfile (stderr);
+  flockfile (trace_fp);
 #endif
   trace_save_errno = save_errno;
+  trace_with_errno = with_errno;
   trace_arg_module = module;
   trace_arg_file = file;
   trace_arg_line = line;
+  trace_missing_lf = 0;
+  trace_prefix_done = 0;
 }
 
-
 static void
-do_internal_trace (const char *format, va_list arg_ptr, int with_errno)
+print_internal_trace_prefix (void)
 {
-  fprintf (stderr, "%s:%s:%d: ",
-           trace_arg_module, trace_arg_file, trace_arg_line);
-  vfprintf (stderr, format, arg_ptr);
-  if (with_errno)
-    fprintf (stderr, " errno=%s", strerror (trace_save_errno));
-  fputc ('\n', stderr);
+  if (!trace_prefix_done)
+    {
+      trace_prefix_done = 1;
+      fprintf (trace_fp, "%s:%s:%d: ",
+               trace_arg_module,/* npth_is_protected ()?"":"^",*/
+               trace_arg_file, trace_arg_line);
+    }
 }
 
-void
-_gpgrt_internal_trace_printf (const char *format, ...)
+static void
+do_internal_trace (const char *format, va_list arg_ptr)
 {
-  va_list arg_ptr;
-
-  va_start (arg_ptr, format) ;
-  vfprintf (stderr, format, arg_ptr);
-  va_end (arg_ptr);
+  print_internal_trace_prefix ();
+  vfprintf (trace_fp, format, arg_ptr);
+  if (trace_with_errno)
+    fprintf (trace_fp, " errno=%s", strerror (trace_save_errno));
+  if (*format && format[strlen(format)-1] != '\n')
+    fputc ('\n', trace_fp);
 }
 
-
 void
-_gpgrt_internal_trace (const char *format, ...)
+_gpgrt_internal_trace_printf (const char *format, ...)
 {
   va_list arg_ptr;
 
+  print_internal_trace_prefix ();
   va_start (arg_ptr, format) ;
-  do_internal_trace (format, arg_ptr, 0);
+  vfprintf (trace_fp, format, arg_ptr);
   va_end (arg_ptr);
+  trace_missing_lf = (*format && format[strlen(format)-1] != '\n');
 }
 
 
 void
-_gpgrt_internal_trace_errno (const char *format, ...)
+_gpgrt_internal_trace (const char *format, ...)
 {
   va_list arg_ptr;
 
   va_start (arg_ptr, format) ;
-  do_internal_trace (format, arg_ptr, 1);
+  do_internal_trace (format, arg_ptr);
   va_end (arg_ptr);
 }
 
@@ -283,8 +304,11 @@ void
 _gpgrt_internal_trace_end (void)
 {
   int save_errno = trace_save_errno;
+
+  if (trace_missing_lf)
+    fputc ('\n', trace_fp);
 #ifdef HAVE_FLOCKFILE
-  funlockfile (stderr);
+  funlockfile (trace_fp);
 #endif
   errno = save_errno;
 }
diff --git a/src/w32-estream.c b/src/w32-estream.c
index 722cb69..d9a4d36 100644
--- a/src/w32-estream.c
+++ b/src/w32-estream.c
@@ -133,7 +133,7 @@ set_synchronize (HANDLE hd)
 			GetCurrentProcess (), &new_hd,
 			EVENT_MODIFY_STATE | SYNCHRONIZE, FALSE, 0))
     {
-      trace_errno (("DuplicateHandle failed: ec=%d", (int)GetLastError ()));
+      trace_errno (1, ("DuplicateHandle failed: ec=%d", (int)GetLastError ()));
       /* FIXME: Should translate the error code.  */
       _gpg_err_set_errno (EIO);
       return INVALID_HANDLE_VALUE;
@@ -364,6 +364,10 @@ func_w32_pollable_read (void *cookie, void *buffer, size_t count)
   gpgrt_ssize_t nread;
   struct reader_context_s *ctx;
 
+  trace (("%p: enter buffer=%p count=%u", cookie, buffer, count));
+
+  /* FIXME: implement pending check if COUNT==0 */
+
   ctx = pcookie->reader;
   if (ctx == NULL)
     {
@@ -371,17 +375,20 @@ func_w32_pollable_read (void *cookie, void *buffer, size_t count)
       if (!ctx)
         {
           _gpg_err_set_errno (EBADF);
-          return -1;
+          nread = -1;
+          goto leave;
         }
+      trace (("%p: new reader %p", cookie, pcookie->reader));
     }
 
-  trace (("%p: read buffer=%p, count=%u", ctx, buffer, count));
-
   if (ctx->eof_shortcut)
-    return 0;
+    {
+      nread = 0;
+      goto leave;
+    }
 
   EnterCriticalSection (&ctx->mutex);
-  trace (("%p: readpos: %d, writepos %d", ctx, ctx->readpos, ctx->writepos));
+  trace (("%p: readpos: %d, writepos %d", cookie, ctx->readpos, ctx->writepos));
   if (ctx->readpos == ctx->writepos && !ctx->error)
     {
       /* No data available.  */
@@ -392,12 +399,13 @@ func_w32_pollable_read (void *cookie, void *buffer, size_t count)
       if (pcookie->modeflags & O_NONBLOCK && ! eof)
         {
           _gpg_err_set_errno (EAGAIN);
-          return -1;
+          nread = -1;
+          goto leave;
         }
 
-      trace (("%p: waiting for data", ctx));
+      trace (("%p: waiting for data", cookie));
       WaitForSingleObject (ctx->have_data_ev, INFINITE);
-      trace (("%p: data available", ctx));
+      trace (("%p: data available", cookie));
       EnterCriticalSection (&ctx->mutex);
     }
 
@@ -409,8 +417,9 @@ func_w32_pollable_read (void *cookie, void *buffer, size_t count)
 	return 0;
       if (!ctx->error)
 	{
-	  trace (("%p: EOF but ctx->eof flag not set", ctx));
-          return 0;
+	  trace (("%p: EOF but ctx->eof flag not set", cookie));
+          nread = 0;
+          goto leave;
 	}
       _gpg_err_set_errno (ctx->error_code);
       return -1;
@@ -427,24 +436,29 @@ func_w32_pollable_read (void *cookie, void *buffer, size_t count)
     {
       if (!ResetEvent (ctx->have_data_ev))
 	{
-	  trace (("%p: ResetEvent failed: ec=%d", ctx, (int)GetLastError ()));
+	  trace (("%p: ResetEvent failed: ec=%d",
+                  cookie, (int)GetLastError ()));
           LeaveCriticalSection (&ctx->mutex);
 	  /* FIXME: Should translate the error code.  */
 	  _gpg_err_set_errno (EIO);
-	  return -1;
+	  nread = -1;
+          goto leave;
 	}
     }
   if (!SetEvent (ctx->have_space_ev))
     {
       trace (("%p: SetEvent (%p) failed: ec=%d",
-              ctx, ctx->have_space_ev, (int)GetLastError ()));
+              cookie, ctx->have_space_ev, (int)GetLastError ()));
       LeaveCriticalSection (&ctx->mutex);
       /* FIXME: Should translate the error code.  */
       _gpg_err_set_errno (EIO);
-      return -1;
+      nread = -1;
+      goto leave;
     }
   LeaveCriticalSection (&ctx->mutex);
 
+ leave:
+  trace_errno (nread==-1,("%p: leave nread=%d", cookie, (int)nread));
   return nread;
 }
 
@@ -653,21 +667,29 @@ func_w32_pollable_write (void *cookie, const void *buffer, size_t count)
 {
   estream_cookie_w32_pollable_t pcookie = cookie;
   struct writer_context_s *ctx = pcookie->writer;
+  int nwritten;
 
-  trace (("%p: buffer: %p count: %d", ctx, buffer, count));
+  trace (("%p: enter buffer: %p count: %d", cookie, buffer, count));
   if (count == 0)
-    return 0;
+    {
+      nwritten = 0;
+      goto leave;
+    }
 
   if (ctx == NULL)
     {
       pcookie->writer = ctx = create_writer (pcookie);
       if (!ctx)
-        return -1;
+        {
+          nwritten = -1;
+          goto leave;
+        }
+      trace (("%p: new writer %p", cookie, pcookie->writer));
     }
 
   EnterCriticalSection (&ctx->mutex);
   trace (("%p: buffer: %p, count: %d, nbytes: %d",
-          ctx, buffer, count, ctx->nbytes));
+          cookie, buffer, count, ctx->nbytes));
   if (!ctx->error && ctx->nbytes)
     {
       /* Bytes are pending for send.  */
@@ -675,24 +697,27 @@ func_w32_pollable_write (void *cookie, const void *buffer, size_t count)
       /* Reset the is_empty event.  Better safe than sorry.  */
       if (!ResetEvent (ctx->is_empty))
 	{
-          trace (("%p: ResetEvent failed: ec=%d", ctx, (int)GetLastError ()));
+          trace (("%p: ResetEvent failed: ec=%d",
+                  cookie, (int)GetLastError ()));
           LeaveCriticalSection (&ctx->mutex);
 	  /* FIXME: Should translate the error code.  */
 	  _gpg_err_set_errno (EIO);
-	  return -1;
+	  nwritten = -1;
+          goto leave;
 	}
       LeaveCriticalSection (&ctx->mutex);
 
       if (pcookie->modeflags & O_NONBLOCK)
         {
-          trace (("%p: would block", ctx));
+          trace (("%p: would block", cookie));
           _gpg_err_set_errno (EAGAIN);
-          return -1;
+          nwritten = -1;
+          goto leave;
         }
 
-      trace (("%p: waiting for empty buffer", ctx));
+      trace (("%p: waiting for empty buffer", cookie));
       WaitForSingleObject (ctx->is_empty, INFINITE);
-      trace (("%p: buffer is empty", ctx));
+      trace (("%p: buffer is empty", cookie));
       EnterCriticalSection (&ctx->mutex);
     }
 
@@ -703,7 +728,8 @@ func_w32_pollable_write (void *cookie, const void *buffer, size_t count)
         _gpg_err_set_errno (EPIPE);
       else
         _gpg_err_set_errno (EIO);
-      return -1;
+      nwritten = -1;
+      goto leave;
     }
 
   /* If no error occurred, the number of bytes in the buffer must be
@@ -719,25 +745,29 @@ func_w32_pollable_write (void *cookie, const void *buffer, size_t count)
      used by the select() implementation to probe the channel.  */
   if (!ResetEvent (ctx->is_empty))
     {
-      trace (("%p: ResetEvent failed: ec=%d", ctx, (int)GetLastError ()));
+      trace (("%p: ResetEvent failed: ec=%d", cookie, (int)GetLastError ()));
       LeaveCriticalSection (&ctx->mutex);
       /* FIXME: Should translate the error code.  */
       _gpg_err_set_errno (EIO);
-      return -1;
+      nwritten = -1;
+      goto leave;
     }
   if (!SetEvent (ctx->have_data))
     {
-      trace (("%p: SetEvent failed: ec=%d", ctx, (int)GetLastError ()));
+      trace (("%p: SetEvent failed: ec=%d", cookie, (int)GetLastError ()));
       LeaveCriticalSection (&ctx->mutex);
       /* FIXME: Should translate the error code.  */
       _gpg_err_set_errno (EIO);
-      return -1;
+      nwritten = -1;
+      goto leave;
     }
-  trace (("%p: nwritten=%d", ctx, count));
   LeaveCriticalSection (&ctx->mutex);
-  trace (("%p: pollable write buffer - leave", ctx));
 
-  return (int) count;
+  nwritten = count;
+
+ leave:
+  trace_errno (nwritten==-1,("%p: leave nwritten=%d", cookie, nwritten));
+  return nwritten;
 }
 
 
@@ -746,6 +776,7 @@ _gpgrt_w32_poll (gpgrt_poll_t *fds, size_t nfds, int timeout)
 {
   HANDLE waitbuf[MAXIMUM_WAIT_OBJECTS];
   int waitidx[MAXIMUM_WAIT_OBJECTS];
+  char waitinfo[MAXIMUM_WAIT_OBJECTS];
   unsigned int code;
   int nwait;
   int i;
@@ -756,7 +787,6 @@ _gpgrt_w32_poll (gpgrt_poll_t *fds, size_t nfds, int timeout)
  restart:
 #endif
 
-  trace_start (("poll on [ "));
   any = 0;
   nwait = 0;
   count = 0;
@@ -782,7 +812,6 @@ _gpgrt_w32_poll (gpgrt_poll_t *fds, size_t nfds, int timeout)
 	  if (fds[i].want_read)
 	    {
 	      struct reader_context_s *ctx = pcookie->reader;
-              trace_append (("%d/read ", i));
               if (ctx == NULL)
                 {
                   pcookie->reader = ctx = create_reader (pcookie);
@@ -792,48 +821,56 @@ _gpgrt_w32_poll (gpgrt_poll_t *fds, size_t nfds, int timeout)
                       _gpg_err_set_errno (EBADF);
                       return -1;
                     }
+                  trace (("%p: new reader %p", pcookie, pcookie->reader));
                 }
+              trace (("%p: using reader %p", pcookie, pcookie->reader));
 
               if (nwait >= DIM (waitbuf))
                 {
-                  trace_finish (("oops ]: Too many objects for WFMO!"));
+                  trace (("oops: too many objects for WFMO"));
                   /* FIXME: Should translate the error code.  */
                   _gpg_err_set_errno (EIO);
                   return -1;
                 }
               waitidx[nwait] = i;
+              waitinfo[nwait] = 'r';
               waitbuf[nwait++] = ctx->have_data_ev;
 	      any = 1;
             }
 	  else if (fds[i].want_write)
 	    {
 	      struct writer_context_s *ctx = pcookie->writer;
-              trace_append (("%d/write ", i));
               if (ctx == NULL)
                 {
                   pcookie->writer = ctx = create_writer (pcookie);
                   if (!ctx)
                     {
-                      trace_finish (("oops ]: create writer failed"));
+                      trace (("oops: create writer failed"));
                       /* FIXME:  Is the error code appropriate?  */
                       _gpg_err_set_errno (EBADF);
                       return -1;
                     }
+                  trace (("%p: new writer %p", pcookie, pcookie->writer));
                 }
+              trace (("%p: using writer %p", pcookie, pcookie->writer));
 
               if (nwait >= DIM (waitbuf))
                 {
-                  trace_finish (("oops ]: Too many objects for WFMO"));
+                  trace (("oops: Too many objects for WFMO"));
                   /* FIXME: Should translate the error code.  */
                   _gpg_err_set_errno (EIO);
                   return -1;
                 }
               waitidx[nwait] = i;
+              waitinfo[nwait] = 'w';
               waitbuf[nwait++] = ctx->is_empty;
 	      any = 1;
             }
         }
     }
+  trace_start (("poll on [ "));
+  for (i = 0; i < nwait; i++)
+    trace_append (("%d/%c ", waitidx[i], waitinfo[i]));
   trace_finish (("]"));
   if (!any)
     return 0;
@@ -956,6 +993,7 @@ _gpgrt_w32_pollable_create (void *_GPGRT__RESTRICT *_GPGRT__RESTRICT cookie,
       err = 0;
     }
 
+  trace_errno (err,("cookie=%p", *cookie));
   return err;
 }