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)
--
2.7.4