protocol: Enhance "unexpected end of file when reading from daemon" error.
[libguestfs.git] / src / proto.c
index ad173c6..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
@@ -70,6 +70,9 @@
 #include "guestfs-internal-actions.h"
 #include "guestfs_protocol.h"
 
+/* Size of guestfs_progress message on the wire. */
+#define PROGRESS_MESSAGE_SIZE 24
+
 /* This is the code used to send and receive RPC messages and (for
  * certain types of message) to perform file transfers.  This code is
  * driven from the generated actions (src/actions.c).  There
  * 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)
 {
@@ -136,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)
 {
@@ -173,15 +218,14 @@ guestfs___end_busy (guestfs_h *g)
 static void
 child_cleanup (guestfs_h *g)
 {
-  if (g->verbose)
-    fprintf (stderr, "child_cleanup: %p: child process died\n", g);
+  debug (g, "child_cleanup: %p: child process died", g);
 
   /*if (g->pid > 0) kill (g->pid, SIGTERM);*/
   if (g->recoverypid > 0) kill (g->recoverypid, 9);
   waitpid (g->pid, NULL, 0);
   if (g->recoverypid > 0) waitpid (g->recoverypid, NULL, 0);
-  close (g->fd[0]);
-  close (g->fd[1]);
+  if (g->fd[0] >= 0) close (g->fd[0]);
+  if (g->fd[1] >= 0) close (g->fd[1]);
   close (g->sock);
   g->fd[0] = -1;
   g->fd[1] = -1;
@@ -190,8 +234,7 @@ child_cleanup (guestfs_h *g)
   g->recoverypid = 0;
   memset (&g->launch_t, 0, sizeof g->launch_t);
   g->state = CONFIG;
-  if (g->subprocess_quit_cb)
-    g->subprocess_quit_cb (g, g->subprocess_quit_cb_data);
+  guestfs___call_callbacks_void (g, GUESTFS_EVENT_SUBPROCESS_QUIT);
 }
 
 static int
@@ -201,17 +244,22 @@ read_log_message_or_eof (guestfs_h *g, int fd, int error_if_eof)
   int n;
 
 #if 0
-  if (g->verbose)
-    fprintf (stderr,
-             "read_log_message_or_eof: %p g->state = %d, fd = %d\n",
-             g, g->state, fd);
+  debug (g, "read_log_message_or_eof: %p g->state = %d, fd = %d",
+         g, g->state, fd);
 #endif
 
   /* 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. */
@@ -234,49 +282,141 @@ read_log_message_or_eof (guestfs_h *g, int fd, int error_if_eof)
     return -1;
   }
 
-  /* In verbose mode, copy all log messages to stderr. */
-  if (g->verbose)
-    ignore_value (write (STDERR_FILENO, buf, n));
-
   /* It's an actual log message, send it upwards if anyone is listening. */
-  if (g->log_message_cb)
-    g->log_message_cb (g, g->log_message_cb_data, buf, n);
+  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;
 }
 
+/* Read 'n' bytes, setting the socket to blocking temporarily so
+ * that we really read the number of bytes requested.
+ * Returns:  0 == EOF while reading
+ *          -1 == error, error() function has been called
+ *           n == read 'n' bytes in full
+ */
+static ssize_t
+really_read_from_socket (guestfs_h *g, int sock, char *buf, size_t n)
+{
+  long flags;
+  ssize_t r;
+  size_t got;
+
+  /* Set socket to blocking. */
+  flags = fcntl (sock, F_GETFL);
+  if (flags == -1) {
+    perrorf (g, "fcntl");
+    return -1;
+  }
+  if (fcntl (sock, F_SETFL, flags & ~O_NONBLOCK) == -1) {
+    perrorf (g, "fcntl");
+    return -1;
+  }
+
+  got = 0;
+  while (got < n) {
+    r = read (sock, &buf[got], n-got);
+    if (r == -1) {
+      perrorf (g, "read");
+      return -1;
+    }
+    if (r == 0)
+      return 0; /* EOF */
+    got += r;
+  }
+
+  /* Restore original socket flags. */
+  if (fcntl (sock, F_SETFL, flags) == -1) {
+    perrorf (g, "fcntl");
+    return -1;
+  }
+
+  return (ssize_t) got;
+}
+
+/* Convenient wrapper to generate a progress message callback. */
+void
+guestfs___progress_message_callback (guestfs_h *g,
+                                     const guestfs_progress *message)
+{
+  uint64_t array[4];
+
+  array[0] = message->proc;
+  array[1] = message->serial;
+  array[2] = message->position;
+  array[3] = message->total;
+
+  guestfs___call_callbacks_array (g, GUESTFS_EVENT_PROGRESS,
+                                  array, sizeof array / sizeof array[0]);
+}
+
 static int
 check_for_daemon_cancellation_or_eof (guestfs_h *g, int fd)
 {
+  char summary[MAX_MESSAGE_SUMMARY];
   char buf[4];
-  int n;
+  ssize_t n;
   uint32_t flag;
   XDR xdr;
 
-  if (g->verbose)
-    fprintf (stderr,
-             "check_for_daemon_cancellation_or_eof: %p g->state = %d, fd = %d\n",
-             g, g->state, fd);
-
-  n = read (fd, buf, 4);
+  n = really_read_from_socket (g, fd, buf, 4);
+  if (n == -1)
+    return -1;
   if (n == 0) {
     /* Hopefully this indicates the qemu child process has died. */
     child_cleanup (g);
     return -1;
   }
 
-  if (n == -1) {
-    if (errno == EINTR || errno == EAGAIN)
-      return 0;
-
-    perrorf (g, "read");
-    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);
 
+  /* Read and process progress messages that happen during FileIn. */
+  if (flag == GUESTFS_PROGRESS_FLAG) {
+    char buf[PROGRESS_MESSAGE_SIZE];
+
+    n = really_read_from_socket (g, fd, buf, PROGRESS_MESSAGE_SIZE);
+    if (n == -1)
+      return -1;
+    if (n == 0) {
+      child_cleanup (g);
+      return -1;
+    }
+
+    if (g->state == BUSY) {
+      guestfs_progress message;
+
+      xdrmem_create (&xdr, buf, PROGRESS_MESSAGE_SIZE, XDR_DECODE);
+      xdr_guestfs_progress (&xdr, &message);
+      xdr_destroy (&xdr);
+
+      guestfs___progress_message_callback (g, &message);
+    }
+
+    return 0;
+  }
+
   if (flag != GUESTFS_CANCEL_FLAG) {
     error (g, _("check_for_daemon_cancellation_or_eof: read 0x%x from daemon, expected 0x%x\n"),
            flag, GUESTFS_CANCEL_FLAG);
@@ -304,15 +444,16 @@ 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];
 
-  if (g->verbose)
-    fprintf (stderr,
-             "send_to_daemon: %p g->state = %d, n = %zu\n", 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);
 
-  FD_SET (g->fd[1], &rset);     /* Read qemu stdout for log messages & EOF. */
+  if (g->fd[1] >= 0)            /* Read qemu stdout for log messages & EOF. */
+    FD_SET (g->fd[1], &rset);
   FD_SET (g->sock, &rset);      /* Read socket for cancellation & EOF. */
   FD_SET (g->sock, &wset);      /* Write to socket to send the data. */
 
@@ -329,14 +470,25 @@ guestfs___send_to_daemon (guestfs_h *g, const void *v_buf, size_t n)
       return -1;
     }
 
-    if (FD_ISSET (g->fd[1], &rset2)) {
+    if (g->fd[1] >= 0 && FD_ISSET (g->fd[1], &rset2)) {
       if (read_log_message_or_eof (g, g->fd[1], 0) == -1)
         return -1;
     }
     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);
@@ -373,20 +525,41 @@ guestfs___send_to_daemon (guestfs_h *g, const void *v_buf, size_t n)
  *
  * It also checks for EOF (qemu died) and passes that up through the
  * child_cleanup function above.
+ *
+ * Progress notifications are handled transparently by this function.
+ * If the callback exists, it is called.  The caller of this function
+ * 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;
 
-  if (g->verbose)
-    fprintf (stderr,
-             "recv_from_daemon: %p g->state = %d, size_rtn = %p, buf_rtn = %p\n",
-             g, g->state, size_rtn, buf_rtn);
-
   FD_ZERO (&rset);
 
-  FD_SET (g->fd[1], &rset);     /* Read qemu stdout for log messages & EOF. */
+  if (g->fd[1] >= 0)            /* Read qemu stdout for log messages & EOF. */
+    FD_SET (g->fd[1], &rset);
   FD_SET (g->sock, &rset);      /* Read socket for data & EOF. */
 
   int max_fd = MAX (g->sock, g->fd[1]);
@@ -400,7 +573,13 @@ guestfs___recv_from_daemon (guestfs_h *g, uint32_t *size_rtn, void **buf_rtn)
    */
   ssize_t nr = -4;
 
-  while (nr < (ssize_t) *size_rtn) {
+  for (;;) {
+    ssize_t message_size =
+      *size_rtn != GUESTFS_PROGRESS_FLAG ?
+      *size_rtn : PROGRESS_MESSAGE_SIZE;
+    if (nr >= message_size)
+      break;
+
     rset2 = rset;
     int r = select (max_fd+1, &rset2, NULL, NULL, NULL);
     if (r == -1) {
@@ -412,7 +591,7 @@ guestfs___recv_from_daemon (guestfs_h *g, uint32_t *size_rtn, void **buf_rtn)
       return -1;
     }
 
-    if (FD_ISSET (g->fd[1], &rset2)) {
+    if (g->fd[1] >= 0 && FD_ISSET (g->fd[1], &rset2)) {
       if (read_log_message_or_eof (g, g->fd[1], 0) == -1) {
         free (*buf_rtn);
         *buf_rtn = NULL;
@@ -436,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;
         }
@@ -450,19 +629,28 @@ guestfs___recv_from_daemon (guestfs_h *g, uint32_t *size_rtn, void **buf_rtn)
         xdr_uint32_t (&xdr, size_rtn);
         xdr_destroy (&xdr);
 
+        /* *size_rtn changed, recalculate message_size */
+        message_size =
+          *size_rtn != GUESTFS_PROGRESS_FLAG ?
+          *size_rtn : PROGRESS_MESSAGE_SIZE;
+
         if (*size_rtn == GUESTFS_LAUNCH_FLAG) {
           if (g->state != LAUNCHING)
             error (g, _("received magic signature from guestfsd, but in state %d"),
                    g->state);
           else {
             g->state = READY;
-            if (g->launch_done_cb)
-              g->launch_done_cb (g, g->launch_done_cb_data);
+            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
          * synchronization.
          */
@@ -473,11 +661,11 @@ guestfs___recv_from_daemon (guestfs_h *g, uint32_t *size_rtn, void **buf_rtn)
         }
 
         /* Allocate the complete buffer, size now known. */
-        *buf_rtn = safe_malloc (g, *size_rtn);
+        *buf_rtn = safe_malloc (g, message_size);
         /*FALLTHROUGH*/
       }
 
-      size_t sizetoread = *size_rtn - nr;
+      size_t sizetoread = message_size - nr;
       if (sizetoread > BUFSIZ) sizetoread = BUFSIZ;
 
       r = read (g->sock, (char *) (*buf_rtn) + nr, sizetoread);
@@ -490,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;
@@ -524,6 +712,27 @@ guestfs___recv_from_daemon (guestfs_h *g, uint32_t *size_rtn, void **buf_rtn)
   }
 #endif
 
+  if (*size_rtn == GUESTFS_PROGRESS_FLAG) {
+    if (g->state == BUSY) {
+      guestfs_progress message;
+      XDR xdr;
+      xdrmem_create (&xdr, *buf_rtn, PROGRESS_MESSAGE_SIZE, XDR_DECODE);
+      xdr_guestfs_progress (&xdr, &message);
+      xdr_destroy (&xdr);
+
+      guestfs___progress_message_callback (g, &message);
+    }
+
+    free (*buf_rtn);
+    *buf_rtn = NULL;
+
+    /* Process next message. */
+    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;
 }
 
@@ -537,13 +746,12 @@ guestfs___accept_from_daemon (guestfs_h *g)
 {
   fd_set rset, rset2;
 
-  if (g->verbose)
-    fprintf (stderr,
-             "accept_from_daemon: %p g->state = %d\n", g, g->state);
+  debug (g, "accept_from_daemon: %p g->state = %d", g, g->state);
 
   FD_ZERO (&rset);
 
-  FD_SET (g->fd[1], &rset);     /* Read qemu stdout for log messages & EOF. */
+  if (g->fd[1] >= 0)            /* Read qemu stdout for log messages & EOF. */
+    FD_SET (g->fd[1], &rset);
   FD_SET (g->sock, &rset);      /* Read socket for accept. */
 
   int max_fd = MAX (g->sock, g->fd[1]);
@@ -567,7 +775,7 @@ guestfs___accept_from_daemon (guestfs_h *g)
       return -1;
     }
 
-    if (FD_ISSET (g->fd[1], &rset2)) {
+    if (g->fd[1] >= 0 && FD_ISSET (g->fd[1], &rset2)) {
       if (read_log_message_or_eof (g, g->fd[1], 1) == -1)
         return -1;
     }
@@ -586,7 +794,9 @@ guestfs___accept_from_daemon (guestfs_h *g)
 }
 
 int
-guestfs___send (guestfs_h *g, int proc_nr, xdrproc_t xdrp, char *args)
+guestfs___send (guestfs_h *g, int proc_nr,
+                uint64_t progress_hint, uint64_t optargs_bitmask,
+                xdrproc_t xdrp, char *args)
 {
   struct guestfs_message_header hdr;
   XDR xdr;
@@ -617,6 +827,8 @@ guestfs___send (guestfs_h *g, int proc_nr, xdrproc_t xdrp, char *args)
   hdr.direction = GUESTFS_DIRECTION_CALL;
   hdr.serial = serial;
   hdr.status = GUESTFS_STATUS_OK;
+  hdr.progress_hint = progress_hint;
+  hdr.optargs_bitmask = optargs_bitmask;
 
   if (!xdr_guestfs_message_header (&xdr, &hdr)) {
     error (g, _("xdr_guestfs_message_header failed"));
@@ -682,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;
   }
 
@@ -794,8 +1003,7 @@ send_file_chunk (guestfs_h *g, int cancel, const char *buf, size_t buflen)
 
   /* Did the daemon send a cancellation message? */
   if (r == -2) {
-    if (g->verbose)
-      fprintf (stderr, "got daemon cancellation\n");
+    debug (g, "got daemon cancellation");
     return -2;
   }
 
@@ -869,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 */
@@ -916,9 +1152,8 @@ guestfs___recv_file (guestfs_h *g, const char *filename)
   char fbuf[4];
   uint32_t flag = GUESTFS_CANCEL_FLAG;
 
-  if (g->verbose)
-    fprintf (stderr, "%s: waiting for daemon to acknowledge cancellation\n",
-             __func__);
+  debug (g, "%s: waiting for daemon to acknowledge cancellation",
+         __func__);
 
   xdrmem_create (&xdr, fbuf, sizeof fbuf, XDR_ENCODE);
   xdr_uint32_t (&xdr, &flag);