protocol: Enhance "unexpected end of file when reading from daemon" error.
[libguestfs.git] / src / proto.c
index fb582cf..d8b1048 100644 (file)
@@ -1,5 +1,5 @@
 /* libguestfs
- * Copyright (C) 2009-2010 Red Hat Inc.
+ * Copyright (C) 2009-2011 Red Hat Inc.
  *
  * This library is free software; you can redistribute it and/or
  * modify it under the terms of the GNU Lesser General Public
  * functions send_to_daemon and recv_from_daemon.
  */
 
+/* This is only used on the debug path, to generate a one-line
+ * printable summary of a protocol message.  'workspace' is scratch
+ * space used to format the message, and it must be at least
+ * MAX_MESSAGE_SUMMARY bytes in size.
+ */
+#define MAX_MESSAGE_SUMMARY 200 /* >= 5 * (4 * 3 + 2) + a few bytes overhead */
+
 static int
 xwrite (int fd, const void *v_buf, size_t len)
 {
@@ -139,6 +146,41 @@ xwrite (int fd, const void *v_buf, size_t len)
   return 0;
 }
 
+static const char *
+message_summary (const void *buf, size_t n, char *workspace)
+{
+  const unsigned char *cbuf = buf;
+  size_t i = 0;
+  char *p = workspace;
+  int truncate = 0;
+
+  /* Print only up to 5 x 32 bits of the message.  That is enough to
+   * cover the message length, and the first four fields of the
+   * message header (prog, vers, proc, direction).
+   */
+  if (n > 5 * 4) {
+    n = 5 * 4;
+    truncate = 1;
+  }
+
+  while (n > 0) {
+    sprintf (p, "%02x ", cbuf[i]);
+    p += 3;
+    n--;
+    i++;
+
+    if ((i & 3) == 0) {
+      strcpy (p, "| ");
+      p += 2;
+    }
+  }
+
+  if (truncate)
+    strcpy (p, "...");
+
+  return workspace;
+}
+
 int
 guestfs___set_busy (guestfs_h *g)
 {
@@ -209,8 +251,15 @@ read_log_message_or_eof (guestfs_h *g, int fd, int error_if_eof)
   /* QEMU's console emulates a 16550A serial port.  The real 16550A
    * device has a small FIFO buffer (16 bytes) which means here we see
    * lots of small reads of 1-16 bytes in length, usually single
-   * bytes.
+   * bytes.  Sleeping here for a very brief period groups reads
+   * together (so we usually get a few lines of output at once) and
+   * improves overall throughput, as well as making the event
+   * interface a bit more sane for callers.  With a virtio-serial
+   * based console (not yet implemented) we may be able to remove
+   * this.  XXX
    */
+  usleep (1000);
+
   n = read (fd, buf, sizeof buf);
   if (n == 0) {
     /* Hopefully this indicates the qemu child process has died. */
@@ -236,6 +285,24 @@ read_log_message_or_eof (guestfs_h *g, int fd, int error_if_eof)
   /* It's an actual log message, send it upwards if anyone is listening. */
   guestfs___call_callbacks_message (g, GUESTFS_EVENT_APPLIANCE, buf, n);
 
+  /* This is a gross hack.  See the comment above
+   * guestfs___launch_send_progress.
+   */
+  if (g->state == LAUNCHING) {
+    const char *sentinel;
+    size_t len;
+
+    sentinel = "Linux version"; /* kernel up */
+    len = strlen (sentinel);
+    if (memmem (buf, n, sentinel, len) != NULL)
+      guestfs___launch_send_progress (g, 6);
+
+    sentinel = "Starting /init script"; /* /init running */
+    len = strlen (sentinel);
+    if (memmem (buf, n, sentinel, len) != NULL)
+      guestfs___launch_send_progress (g, 9);
+  }
+
   return 0;
 }
 
@@ -284,8 +351,10 @@ really_read_from_socket (guestfs_h *g, int sock, char *buf, size_t n)
   return (ssize_t) got;
 }
 
-static void
-send_progress_message (guestfs_h *g, const guestfs_progress *message)
+/* Convenient wrapper to generate a progress message callback. */
+void
+guestfs___progress_message_callback (guestfs_h *g,
+                                     const guestfs_progress *message)
 {
   uint64_t array[4];
 
@@ -301,14 +370,12 @@ send_progress_message (guestfs_h *g, const guestfs_progress *message)
 static int
 check_for_daemon_cancellation_or_eof (guestfs_h *g, int fd)
 {
+  char summary[MAX_MESSAGE_SUMMARY];
   char buf[4];
   ssize_t n;
   uint32_t flag;
   XDR xdr;
 
-  debug (g, "check_for_daemon_cancellation_or_eof: %p g->state = %d, fd = %d",
-         g, g->state, fd);
-
   n = really_read_from_socket (g, fd, buf, 4);
   if (n == -1)
     return -1;
@@ -318,6 +385,9 @@ check_for_daemon_cancellation_or_eof (guestfs_h *g, int fd)
     return -1;
   }
 
+  debug (g, "check_for_daemon_cancellation_or_eof: %s",
+         message_summary (buf, 4, summary));
+
   xdrmem_create (&xdr, buf, 4, XDR_DECODE);
   xdr_uint32_t (&xdr, &flag);
   xdr_destroy (&xdr);
@@ -341,7 +411,7 @@ check_for_daemon_cancellation_or_eof (guestfs_h *g, int fd)
       xdr_guestfs_progress (&xdr, &message);
       xdr_destroy (&xdr);
 
-      send_progress_message (g, &message);
+      guestfs___progress_message_callback (g, &message);
     }
 
     return 0;
@@ -374,8 +444,10 @@ guestfs___send_to_daemon (guestfs_h *g, const void *v_buf, size_t n)
   const char *buf = v_buf;
   fd_set rset, rset2;
   fd_set wset, wset2;
+  char summary[MAX_MESSAGE_SUMMARY];
 
-  debug (g, "send_to_daemon: %p g->state = %d, n = %zu", g, g->state, n);
+  debug (g, "send_to_daemon: %zu bytes: %s", n,
+         message_summary (v_buf, n, summary));
 
   FD_ZERO (&rset);
   FD_ZERO (&wset);
@@ -404,8 +476,19 @@ guestfs___send_to_daemon (guestfs_h *g, const void *v_buf, size_t n)
     }
     if (FD_ISSET (g->sock, &rset2)) {
       r = check_for_daemon_cancellation_or_eof (g, g->sock);
-      if (r < 0)
-        return r;
+      if (r == -1)
+       return r;
+      if (r == -2) {
+       /* Daemon sent cancel message.  But to maintain
+        * synchronization we must write out the remainder of the
+        * write buffer before we return (RHBZ#576879).
+        */
+       if (xwrite (g->sock, buf, n) == -1) {
+         perrorf (g, "write");
+         return -1;
+       }
+       return -2; /* cancelled */
+      }
     }
     if (FD_ISSET (g->sock, &wset2)) {
       r = write (g->sock, buf, n);
@@ -448,14 +531,31 @@ guestfs___send_to_daemon (guestfs_h *g, const void *v_buf, size_t n)
  * will not see GUESTFS_PROGRESS_FLAG.
  */
 
+static inline void
+unexpected_end_of_file_from_daemon_error (guestfs_h *g)
+{
+#define UNEXPEOF_ERROR "unexpected end of file when reading from daemon.\n"
+#define UNEXPEOF_TEST_TOOL \
+  "Or you can run 'libguestfs-test-tool' and post the complete output into\n" \
+  "a bug report or message to the libguestfs mailing list."
+  if (!g->verbose)
+    error (g, _(UNEXPEOF_ERROR
+"This usually means the libguestfs appliance failed to start up.  Please\n"
+"enable debugging (LIBGUESTFS_DEBUG=1) and rerun the command, then look at\n"
+"the debug messages output prior to this error.\n"
+UNEXPEOF_TEST_TOOL));
+  else
+    error (g, _(UNEXPEOF_ERROR
+"See earlier debug messages.\n"
+UNEXPEOF_TEST_TOOL));
+}
+
 int
 guestfs___recv_from_daemon (guestfs_h *g, uint32_t *size_rtn, void **buf_rtn)
 {
+  char summary[MAX_MESSAGE_SUMMARY];
   fd_set rset, rset2;
 
-  debug (g, "recv_from_daemon: %p g->state = %d, size_rtn = %p, buf_rtn = %p",
-         g, g->state, size_rtn, buf_rtn);
-
   FD_ZERO (&rset);
 
   if (g->fd[1] >= 0)            /* Read qemu stdout for log messages & EOF. */
@@ -515,7 +615,7 @@ guestfs___recv_from_daemon (guestfs_h *g, uint32_t *size_rtn, void **buf_rtn)
           return -1;
         }
         if (r == 0) {
-          error (g, _("unexpected end of file when reading from daemon"));
+          unexpected_end_of_file_from_daemon_error (g);
           child_cleanup (g);
           return -1;
         }
@@ -542,10 +642,13 @@ guestfs___recv_from_daemon (guestfs_h *g, uint32_t *size_rtn, void **buf_rtn)
             g->state = READY;
             guestfs___call_callbacks_void (g, GUESTFS_EVENT_LAUNCH_DONE);
           }
+          debug (g, "recv_from_daemon: received GUESTFS_LAUNCH_FLAG");
           return 0;
         }
-        else if (*size_rtn == GUESTFS_CANCEL_FLAG)
+        else if (*size_rtn == GUESTFS_CANCEL_FLAG) {
+          debug (g, "recv_from_daemon: received GUESTFS_CANCEL_FLAG");
           return 0;
+        }
         else if (*size_rtn == GUESTFS_PROGRESS_FLAG)
           /*FALLTHROUGH*/;
         /* If this happens, it's pretty bad and we've probably lost
@@ -575,7 +678,7 @@ guestfs___recv_from_daemon (guestfs_h *g, uint32_t *size_rtn, void **buf_rtn)
         return -1;
       }
       if (r == 0) {
-        error (g, _("unexpected end of file when reading from daemon"));
+        unexpected_end_of_file_from_daemon_error (g);
         child_cleanup (g);
         free (*buf_rtn);
         *buf_rtn = NULL;
@@ -617,7 +720,7 @@ guestfs___recv_from_daemon (guestfs_h *g, uint32_t *size_rtn, void **buf_rtn)
       xdr_guestfs_progress (&xdr, &message);
       xdr_destroy (&xdr);
 
-      send_progress_message (g, &message);
+      guestfs___progress_message_callback (g, &message);
     }
 
     free (*buf_rtn);
@@ -627,6 +730,9 @@ guestfs___recv_from_daemon (guestfs_h *g, uint32_t *size_rtn, void **buf_rtn)
     return guestfs___recv_from_daemon (g, size_rtn, buf_rtn);
   }
 
+  debug (g, "recv_from_daemon: %" PRIu32 " bytes: %s", *size_rtn,
+         message_summary (*buf_rtn, *size_rtn, summary));
+
   return 0;
 }
 
@@ -788,9 +894,6 @@ guestfs___send_file (guestfs_h *g, const char *filename)
   if (fd == -1) {
     perrorf (g, "open: %s", filename);
     send_file_cancellation (g);
-    /* Daemon sees cancellation and won't reply, so caller can
-     * just return here.
-     */
     return -1;
   }
 
@@ -974,6 +1077,34 @@ guestfs___recv (guestfs_h *g, const char *fn,
   return 0;
 }
 
+/* Same as guestfs___recv, but it discards the reply message. */
+int
+guestfs___recv_discard (guestfs_h *g, const char *fn)
+{
+  void *buf;
+  uint32_t size;
+  int r;
+
+ again:
+  r = guestfs___recv_from_daemon (g, &size, &buf);
+  if (r == -1)
+    return -1;
+
+  /* This can happen if a cancellation happens right at the end
+   * of us sending a FileIn parameter to the daemon.  Discard.  The
+   * daemon should send us an error message next.
+   */
+  if (size == GUESTFS_CANCEL_FLAG)
+    goto again;
+
+  if (size == GUESTFS_LAUNCH_FLAG) {
+    error (g, "%s: received unexpected launch flag from daemon when expecting reply", fn);
+    return -1;
+  }
+
+  return 0;
+}
+
 /* Receive a file. */
 
 /* Returns -1 = error, 0 = EOF, > 0 = more data */