From f009e084782ac692ce1a519b5255e9abf4a79632 Mon Sep 17 00:00:00 2001

From: "Richard W.M. Jones" <rjones@redhat.com>

Date: Wed, 6 Apr 2016 10:43:00 +0100

Subject: [PATCH] tests/qemu: boot-analysis: Add support for logging libvirt

 events.

(cherry picked from commit b332d91bc9685e8992ede2c8a10655f26fd0395e)

---

 tests/qemu/Makefile.am     |   1 +

 tests/qemu/boot-analysis.c | 236 +++++++++++++++++++++++++++++++++++++++++++--

 2 files changed, 227 insertions(+), 10 deletions(-)

diff --git a/tests/qemu/Makefile.am b/tests/qemu/Makefile.am

index cc5cb6a..fdf643f 100644

--- a/tests/qemu/Makefile.am

+++ b/tests/qemu/Makefile.am

@@ -84,6 +84,7 @@ boot_analysis_CPPFLAGS = \

 	-I$(top_srcdir)/gnulib/lib -I$(top_builddir)/gnulib/lib \

 	-I$(top_srcdir)/src -I$(top_builddir)/src

 boot_analysis_CFLAGS = \

+	-pthread \

 	$(WARN_CFLAGS) $(WERROR_CFLAGS) \

 	$(PCRE_CFLAGS)

 boot_analysis_LDADD = \

diff --git a/tests/qemu/boot-analysis.c b/tests/qemu/boot-analysis.c

index 37d8b3c..2a43976 100644

--- a/tests/qemu/boot-analysis.c

+++ b/tests/qemu/boot-analysis.c

@@ -64,6 +64,7 @@

 #include <inttypes.h>

 #include <string.h>

 #include <unistd.h>

+#include <fcntl.h>

 #include <getopt.h>

 #include <limits.h>

 #include <time.h>

@@ -71,7 +72,10 @@

 #include <error.h>

 #include <ctype.h>

 #include <assert.h>

+#include <sys/types.h>

+#include <sys/wait.h>

 #include <math.h>

+#include <pthread.h>

 #include "guestfs.h"

 #include "guestfs-internal-frontend.h"

@@ -84,20 +88,32 @@

  */

 #define WARNING_THRESHOLD 1.0

-struct pass_data pass_data[NR_TEST_PASSES];

-size_t nr_activities;

-struct activity *activities;

-

 static const char *append = NULL;

 static int force_colour = 0;

 static int memsize = 0;

 static int smp = 1;

 static int verbose = 0;

+static int libvirt_pipe[2] = { -1, -1 };

+static ssize_t libvirt_pass = -1;

+

+/* Because there is a separate thread which collects libvirt log data,

+ * we must protect the pass_data struct with a mutex.  This only

+ * applies during the data collection passes.

+ */

+static pthread_mutex_t pass_data_lock = PTHREAD_MUTEX_INITIALIZER;

+struct pass_data pass_data[NR_TEST_PASSES];

+

+size_t nr_activities;

+struct activity *activities;

+

 static void run_test (void);

 static struct event *add_event (struct pass_data *, uint64_t source);

 static guestfs_h *create_handle (void);

 static void set_up_event_handlers (guestfs_h *g, size_t pass);

+static void libvirt_log_hack (int argc, char **argv);

+static void start_libvirt_thread (size_t pass);

+static void stop_libvirt_thread (void);

 static void add_drive (guestfs_h *g);

 static void check_pass_data (void);

 static void dump_pass_data (void);

@@ -152,6 +168,8 @@ main (int argc, char *argv[])

     { "color", 0, 0, 0 },

     { "colour", 0, 0, 0 },

     { "memsize", 1, 0, 'm' },

+    { "libvirt-pipe-0", 1, 0, 0 }, /* see libvirt_log_hack */

+    { "libvirt-pipe-1", 1, 0, 0 },

     { "smp", 1, 0, 0 },

     { "verbose", 0, 0, 'v' },

     { 0, 0, 0, 0 }

@@ -173,12 +191,22 @@ main (int argc, char *argv[])

         force_colour = 1;

         break;

       }

+      else if (STREQ (long_options[option_index].name, "libvirt-pipe-0")) {

+        if (sscanf (optarg, "%d", &libvirt_pipe[0]) != 1)

+          error (EXIT_FAILURE, 0,

+                 "could not parse libvirt-pipe-0 parameter: %s", optarg);

+        break;

+      }

+      else if (STREQ (long_options[option_index].name, "libvirt-pipe-1")) {

+        if (sscanf (optarg, "%d", &libvirt_pipe[1]) != 1)

+          error (EXIT_FAILURE, 0,

+                 "could not parse libvirt-pipe-1 parameter: %s", optarg);

+        break;

+      }

       else if (STREQ (long_options[option_index].name, "smp")) {

-        if (sscanf (optarg, "%d", &smp) != 1) {

-          fprintf (stderr, "%s: could not parse smp parameter: %s\n",

-                   guestfs_int_program_name, optarg);

-          exit (EXIT_FAILURE);

-        }

+        if (sscanf (optarg, "%d", &smp) != 1)

+          error (EXIT_FAILURE, 0,

+                 "could not parse smp parameter: %s", optarg);

         break;

       }

       fprintf (stderr, "%s: unknown long option: %s (%d)\n",

@@ -205,6 +233,8 @@ main (int argc, char *argv[])

     }

   }

+  libvirt_log_hack (argc, argv);

+

   if (STRNEQ (host_cpu, "x86_64"))

     fprintf (stderr, "WARNING: host_cpu != x86_64: This program may not work or give bogus results.\n");

@@ -230,10 +260,12 @@ run_test (void)

   for (i = 0; i < NR_TEST_PASSES; ++i) {

     g = create_handle ();

     set_up_event_handlers (g, i);

+    start_libvirt_thread (i);

     add_drive (g);

     if (guestfs_launch (g) == -1)

       exit (EXIT_FAILURE);

     guestfs_close (g);

+    stop_libvirt_thread ();

     printf ("    pass %zu: %zu events collected in %" PRIi64 " ns\n",

             i+1, pass_data[i].nr_events, pass_data[i].elapsed_ns);

@@ -266,7 +298,7 @@ run_test (void)

 }

 static struct event *

-add_event (struct pass_data *data, uint64_t source)

+add_event_unlocked (struct pass_data *data, uint64_t source)

 {

   struct event *ret;

@@ -282,6 +314,17 @@ add_event (struct pass_data *data, uint64_t source)

   return ret;

 }

+static struct event *

+add_event (struct pass_data *data, uint64_t source)

+{

+  struct event *ret;

+

+  pthread_mutex_lock (&pass_data_lock);

+  ret = add_event_unlocked (data, source);

+  pthread_mutex_unlock (&pass_data_lock);

+  return ret;

+}

+

 /* Common function to create the handle and set various defaults. */

 static guestfs_h *

 create_handle (void)

@@ -590,6 +633,179 @@ set_up_event_handlers (guestfs_h *g, size_t pass)

   guestfs_set_trace (g, 1);

 }

+/* libvirt debugging sucks in a number of concrete ways:

+ *

+ * - you can't get a synchronous callback from a log message

+ * - you can't enable logging per handle (only globally

+ *   by setting environment variables)

+ * - you can't debug the daemon easily

+ * - it's very complex

+ * - it's very complex but not in ways that are practical or useful

+ *

+ * To get log messages at all, we need to create a pipe connected to a

+ * second thread, and when libvirt prints something to the pipe we log

+ * that.

+ *

+ * However that's not sufficient.  Because logging is only enabled

+ * when libvirt examines environment variables at the start of the

+ * program, we need to create the pipe and then fork+exec a new

+ * instance of the whole program with the pipe and environment

+ * variables set up.

+ */

+static int is_libvirt_backend (guestfs_h *g);

+static void *libvirt_log_thread (void *datavp);

+

+static void

+libvirt_log_hack (int argc, char **argv)

+{

+  guestfs_h *g;

+

+  g = guestfs_create ();

+  if (!is_libvirt_backend (g)) {

+    guestfs_close (g);

+    return;

+  }

+  guestfs_close (g);

+

+  /* Have we set up the pipes and environment and forked yet?  If not,

+   * do that first.

+   */

+  if (libvirt_pipe[0] == -1 || libvirt_pipe[1] == -1) {

+    char log_outputs[64];

+    char **new_argv;

+    char param1[64], param2[64];

+    size_t i;

+    pid_t pid;

+    int status;

+

+    /* Create the pipe.  NB: do NOT use O_CLOEXEC since we want to pass

+     * this pipe into a child process.

+     */

+    if (pipe (libvirt_pipe) == -1)

+      error (EXIT_FAILURE, 0, "pipe2");

+

+    /* Create the environment variables to enable logging in libvirt. */

+    setenv ("LIBVIRT_DEBUG", "1", 1);

+    snprintf (log_outputs, sizeof log_outputs,

+              "1:file:/dev/fd/%d", libvirt_pipe[1]);

+    setenv ("LIBVIRT_LOG_OUTPUTS", log_outputs, 1);

+

+    /* Run self again. */

+    new_argv = malloc ((argc+3) * sizeof (char *));

+    if (new_argv == NULL)

+      error (EXIT_FAILURE, errno, "malloc");

+

+    for (i = 0; i < (size_t) argc; ++i)

+      new_argv[i] = argv[i];

+

+    snprintf (param1, sizeof param1, "--libvirt-pipe-0=%d", libvirt_pipe[0]);

+    new_argv[argc] = param1;

+    snprintf (param2, sizeof param2, "--libvirt-pipe-1=%d", libvirt_pipe[1]);

+    new_argv[argc+1] = param2;

+    new_argv[argc+2] = NULL;

+

+    pid = fork ();

+    if (pid == -1)

+      error (EXIT_FAILURE, errno, "fork");

+    if (pid == 0) {             /* Child process. */

+      execvp (argv[0], new_argv);

+      perror ("execvp");

+      _exit (EXIT_FAILURE);

+    }

+

+    if (waitpid (pid, &status, 0) == -1)

+      error (EXIT_FAILURE, errno, "waitpid");

+    if (WIFEXITED (status))

+      exit (WEXITSTATUS (status));

+    error (EXIT_FAILURE, 0, "unexpected exit status from process: %d", status);

+  }

+

+  /* If we reach this else clause, then we have forked.  Now we must

+   * create a thread to read events from the pipe.  This must be

+   * constantly reading from the pipe, otherwise we will deadlock.

+   * During the warm-up phase we end up throwing away messages.

+   */

+  else {

+    pthread_t thread;

+    pthread_attr_t attr;

+    int r;

+

+    r = pthread_attr_init (&attr);

+    if (r != 0)

+      error (EXIT_FAILURE, r, "pthread_attr_init");

+    r = pthread_attr_setdetachstate (&attr, PTHREAD_CREATE_DETACHED);

+    if (r != 0)

+      error (EXIT_FAILURE, r, "pthread_attr_setdetachstate");

+    r = pthread_create (&thread, &attr, libvirt_log_thread, NULL);

+    if (r != 0)

+      error (EXIT_FAILURE, r, "pthread_create");

+    pthread_attr_destroy (&attr);

+  }

+}

+

+static void

+start_libvirt_thread (size_t pass)

+{

+  /* In the non-libvirt case, this variable is ignored. */

+  pthread_mutex_lock (&pass_data_lock);

+  libvirt_pass = pass;

+  pthread_mutex_unlock (&pass_data_lock);

+}

+

+static void

+stop_libvirt_thread (void)

+{

+  /* In the non-libvirt case, this variable is ignored. */

+  pthread_mutex_lock (&pass_data_lock);

+  libvirt_pass = -1;

+  pthread_mutex_unlock (&pass_data_lock);

+}

+

+/* The separate "libvirt thread".  It loops reading debug messages

+ * printed by libvirt and adds them to the pass_data.

+ */

+static void *

+libvirt_log_thread (void *arg)

+{

+  struct event *event;

+  CLEANUP_FREE char *buf = NULL;

+  ssize_t r;

+

+  buf = malloc (BUFSIZ);

+  if (buf == NULL)

+    error (EXIT_FAILURE, errno, "malloc");

+

+  while ((r = read (libvirt_pipe[0], buf, BUFSIZ)) > 0) {

+    pthread_mutex_lock (&pass_data_lock);

+    if (libvirt_pass == -1) goto discard;

+    event =

+      add_event_unlocked (&pass_data[libvirt_pass], GUESTFS_EVENT_LIBRARY);

+    event->message = strndup (buf, r);

+    if (event->message == NULL)

+      error (EXIT_FAILURE, errno, "strndup");

+  discard:

+    pthread_mutex_unlock (&pass_data_lock);

+  }

+

+  if (r == -1)

+    error (EXIT_FAILURE, errno, "libvirt_log_thread: read");

+

+  /* It's possible for the pipe to be closed (r == 0) if thread

+   * cancellation is delayed after the main thread exits, so just

+   * ignore that case and exit.

+   */

+  pthread_exit (NULL);

+}

+

+static int

+is_libvirt_backend (guestfs_h *g)

+{

+  CLEANUP_FREE char *backend = guestfs_get_backend (g);

+

+  return backend &&

+    (STREQ (backend, "libvirt") || STRPREFIX (backend, "libvirt:"));

+}

+

 /* Sanity check the collected events. */

 static void

 check_pass_data (void)

-- 

1.8.3.1