Implemented test log IPC.
authorTim Janik <timj@src.gnome.org>
Tue, 20 Nov 2007 15:00:45 +0000 (15:00 +0000)
committerTim Janik <timj@src.gnome.org>
Tue, 20 Nov 2007 15:00:45 +0000 (15:00 +0000)
* gtester.c: read and decode log messages from test binary child processes.
fixed GIOChannel and child watch handling to process all messages and avoid
hangs. pass --verbose and --quiet on to children, default to --quiet.

* gtestframework.h: export g_test_log_type_name().

* gtestframework.c: send test log to --GTestLogFD=<fd> if given, removed
bogus -o-option.

svn path=/trunk/; revision=5898

glib/gtester.c
glib/gtestframework.c
glib/gtestframework.h

index db60ee0baacc2b5557d78c629726d130f1685b47..1deb9a5e6d867ac22ab66fe6ce4451cdeb44af81 100644 (file)
 #include <string.h>
 #include <stdlib.h>
 #include <unistd.h>
+#include <unistd.h>
+#include <fcntl.h>
+#include <errno.h>
+#include <signal.h>
 
 /* the read buffer size in bytes */
 #define READ_BUFFER_SIZE 4096
@@ -33,7 +37,7 @@ static void     parse_args      (gint           *argc_p,
 static GIOChannel  *ioc_report = NULL;
 static gboolean     subtest_running = FALSE;
 static gboolean     subtest_io_pending = FALSE;
-static gboolean     gtester_quiet = FALSE;
+static gboolean     gtester_quiet = TRUE;
 static gboolean     gtester_verbose = FALSE;
 static gboolean     gtester_list_tests = FALSE;
 static gboolean     subtest_mode_fatal = FALSE;
@@ -49,32 +53,55 @@ child_report_cb (GIOChannel  *source,
                  GIOCondition condition,
                  gpointer     data)
 {
+  GTestLogBuffer *tlb = data;
   GIOStatus status = G_IO_STATUS_NORMAL;
-
-  while (status == G_IO_STATUS_NORMAL)
+  gsize length = 0;
+  do
     {
-      gchar buffer[READ_BUFFER_SIZE];
-      gsize length = 0;
+      guint8 buffer[READ_BUFFER_SIZE];
       GError *error = NULL;
-      status = g_io_channel_read_chars (source, buffer, sizeof (buffer), &length, &error);
-      switch (status)
+      status = g_io_channel_read_chars (source, (gchar*) buffer, sizeof (buffer), &length, &error);
+      if (length)
         {
-        case G_IO_STATUS_NORMAL:
-          write (2, buffer, length); /* passthrough child's stdout */
-          break;
-        case G_IO_STATUS_AGAIN:
-          /* retry later */
-          break;
-        case G_IO_STATUS_ERROR:
-          /* ignore, child closed fd or similar g_warning ("Error while reading data: %s", error->message); */
-          /* fall through into EOF */
-        case G_IO_STATUS_EOF:
-          subtest_io_pending = FALSE;
-          return FALSE;
+          GTestLogMsg *msg;
+          g_test_log_buffer_push (tlb, length, buffer);
+          do
+            {
+              msg = g_test_log_buffer_pop (tlb);
+              if (msg)
+                {
+                  guint ui;
+                  /* print message, this should be written to an XML log file */
+                  g_printerr ("{*GTLOG(%s)", g_test_log_type_name (msg->log_type));
+                  for (ui = 0; ui < msg->n_strings; ui++)
+                    g_printerr (":{%s}", msg->strings[ui]);
+                  if (msg->n_nums)
+                    {
+                      g_printerr (":(");
+                      for (ui = 0; ui < msg->n_nums; ui++)
+                        g_printerr ("%s%.16Lg", ui ? ";" : "", msg->nums[ui]);
+                      g_printerr (")");
+                    }
+                  g_printerr (":GTLOG*}\n");
+                  g_test_log_msg_free (msg);
+                }
+            }
+          while (msg);
         }
       g_clear_error (&error);
+      /* ignore the io channel status, which seems to be bogus especially for non blocking fds */
+      (void) status;
     }
-  return TRUE;
+  while (length > 0);
+  if (condition & (G_IO_ERR | G_IO_HUP))
+    {
+      /* if there's no data to read and select() reports an error or hangup,
+       * the fd must have been closed remotely
+       */
+      subtest_io_pending = FALSE;
+      return FALSE;
+    }
+  return TRUE; /* keep polling */
 }
 
 static void
@@ -94,18 +121,43 @@ queue_gfree (GSList **slistp,
   return string;
 }
 
+static void
+unset_cloexec_fdp (gpointer fdp_data)
+{
+  int r, *fdp = fdp_data;
+  do
+    r = fcntl (*fdp, F_SETFD, 0 /* FD_CLOEXEC */);
+  while (r < 0 && errno == EINTR);
+}
+
 static void
 launch_test (const char *binary)
 {
+  GTestLogBuffer *tlb;
   GSList *slist, *free_list = NULL;
   GError *error = NULL;
   const gchar *argv[20 + g_slist_length (subtest_paths)];
   GPid pid = 0;
-  gint i = 0, child_report = -1;
+  gint report_pipe[2] = { -1, -1 };
+  gint i = 0;
+
+  if (pipe (report_pipe) < 0)
+    {
+      if (subtest_mode_fatal)
+        g_error ("Failed to open pipe for test binary: %s: %s", binary, g_strerror (errno));
+      else
+        g_warning ("Failed to open pipe for test binary: %s: %s", binary, g_strerror (errno));
+      return;
+    }
 
   /* setup argv */
   argv[i++] = binary;
-  // argv[i++] = "--quiet";
+  if (gtester_quiet)
+    argv[i++] = "--quiet";
+  if (gtester_verbose)
+    argv[i++] = "--verbose";
+  // argv[i++] = "--debug-log";
+  argv[i++] = queue_gfree (&free_list, g_strdup_printf ("--GTestLogFD=%u", report_pipe[1]));
   if (!subtest_mode_fatal)
     argv[i++] = "--keep-going";
   if (subtest_mode_quick)
@@ -122,26 +174,24 @@ launch_test (const char *binary)
     argv[i++] = "-l";
   argv[i++] = NULL;
 
-  /* child_report will be used to capture logging information from the
-   * child binary. for the moment, we just use it to replicate stdout.
-   */
-
   g_spawn_async_with_pipes (NULL, /* g_get_current_dir() */
                             (gchar**) argv,
                             NULL, /* envp */
                             G_SPAWN_DO_NOT_REAP_CHILD, /* G_SPAWN_SEARCH_PATH */
-                            NULL, NULL, /* child_setup, user_data */
+                            unset_cloexec_fdp, &report_pipe[1], /* pre-exec callback */
                             &pid,
                             NULL,       /* standard_input */
-                            &child_report, /* standard_output */
+                            NULL,       /* standard_output */
                             NULL,       /* standard_error */
                             &error);
   g_slist_foreach (free_list, (void(*)(void*,void*)) g_free, NULL);
   g_slist_free (free_list);
   free_list = NULL;
+  close (report_pipe[1]);
 
   if (error)
     {
+      close (report_pipe[0]);
       if (subtest_mode_fatal)
         g_error ("Failed to execute test binary: %s: %s", argv[0], error->message);
       else
@@ -149,14 +199,17 @@ launch_test (const char *binary)
       g_clear_error (&error);
       return;
     }
+
   subtest_running = TRUE;
   subtest_io_pending = TRUE;
-
-  if (child_report >= 0)
+  tlb = g_test_log_buffer_new();
+  if (report_pipe[0] >= 0)
     {
-      ioc_report = g_io_channel_unix_new (child_report);
+      ioc_report = g_io_channel_unix_new (report_pipe[0]);
       g_io_channel_set_flags (ioc_report, G_IO_FLAG_NONBLOCK, NULL);
-      g_io_add_watch_full (ioc_report, G_PRIORITY_DEFAULT - 1, G_IO_IN | G_IO_ERR | G_IO_HUP, child_report_cb, NULL, NULL);
+      g_io_channel_set_encoding (ioc_report, NULL, NULL);
+      g_io_channel_set_buffered (ioc_report, FALSE);
+      g_io_add_watch_full (ioc_report, G_PRIORITY_DEFAULT - 1, G_IO_IN | G_IO_ERR | G_IO_HUP, child_report_cb, tlb, NULL);
       g_io_channel_unref (ioc_report);
     }
   g_child_watch_add_full (G_PRIORITY_DEFAULT + 1, pid, child_watch_cb, NULL, NULL);
@@ -165,6 +218,9 @@ launch_test (const char *binary)
          subtest_io_pending ||          /* FALSE once ioc_report closes */
          g_main_context_pending (NULL)) /* TRUE while idler, etc are running */
     g_main_context_iteration (NULL, TRUE);
+
+  close (report_pipe[0]);
+  g_test_log_buffer_free (tlb);
 }
 
 static void
@@ -322,6 +378,20 @@ main (int    argc,
 {
   guint ui;
 
+  /* some unices need SA_RESTART for SIGCHLD to return -EAGAIN for io.
+   * we must fiddle with sigaction() *before* glib is used, otherwise
+   * we could revoke signal hanmdler setups from glib initialization code.
+   */
+  if (TRUE * 0)
+    {
+      struct sigaction sa;
+      struct sigaction osa;
+      sa.sa_handler = SIG_DFL;
+      sigfillset (&sa.sa_mask);
+      sa.sa_flags = SA_RESTART;
+      sigaction (SIGCHLD, &sa, &osa);
+    }
+
   g_set_prgname (argv[0]);
   parse_args (&argc, &argv);
 
index 30e70ddac356603dd0704bee66e65e34e48292a7..a459f9a417deeaf4fd8e34fa2de3325f254df72a 100644 (file)
@@ -53,7 +53,7 @@ static guint8*                  g_test_log_dump         (GTestLogMsg *msg,
                                                          guint       *len);
 
 /* --- variables --- */
-static int         test_stdmsg = 1;
+static int         test_log_fd = -1;
 static gboolean    test_mode_quick = TRUE;
 static gboolean    test_mode_perf = FALSE;
 static gboolean    test_mode_fatal = TRUE;
@@ -62,7 +62,6 @@ static gboolean    g_test_run_once = TRUE;
 static gboolean    test_run_quiet = FALSE;
 static gboolean    test_run_verbose = FALSE;
 static gboolean    test_run_list = FALSE;
-static gchar      *test_run_output = NULL;
 static gchar      *test_run_seedstr = NULL;
 static GRand      *test_run_rand = NULL;
 static gchar      *test_run_name = "";
@@ -79,10 +78,10 @@ static char       *test_trap_last_stderr = NULL;
 static gboolean    test_debug_log = FALSE;
 
 /* --- functions --- */
-static const char*
-test_log_bit (GTestLogType lbit)
+const char*
+g_test_log_type_name (GTestLogType log_type)
 {
-  switch (lbit)
+  switch (log_type)
     {
     case G_TEST_LOG_START_BINARY:       return "binary";
     case G_TEST_LOG_LIST_CASE:          return "list";
@@ -98,6 +97,13 @@ static void
 g_test_log_send (guint         n_bytes,
                  const guint8 *buffer)
 {
+  if (test_log_fd >= 0)
+    {
+      int r;
+      do
+        r = write (test_log_fd, buffer, n_bytes);
+      while (r < 0 && errno == EINTR);
+    }
   if (test_debug_log)
     {
       GTestLogBuffer *lbuffer = g_test_log_buffer_new();
@@ -109,7 +115,7 @@ g_test_log_send (guint         n_bytes,
       g_assert (lbuffer->data->len == 0); // FIXME: should be g_awrn_if_fail
       g_test_log_buffer_free (lbuffer);
       /* print message */
-      g_printerr ("{*LOG(%s)", test_log_bit (msg->log_type));
+      g_printerr ("{*LOG(%s)", g_test_log_type_name (msg->log_type));
       for (ui = 0; ui < msg->n_strings; ui++)
         g_printerr (":{%s}", msg->strings[ui]);
       if (msg->n_nums)
@@ -205,27 +211,27 @@ parse_args (gint    *argc_p,
           test_debug_log = TRUE;
           argv[i] = NULL;
         }
-      else if (strcmp ("-p", argv[i]) == 0 || strncmp ("-p=", argv[i], 3) == 0)
+      else if (strcmp ("--GTestLogFD", argv[i]) == 0 || strncmp ("--GTestLogFD=", argv[i], 13) == 0)
         {
-          gchar *equal = argv[i] + 2;
+          gchar *equal = argv[i] + 12;
           if (*equal == '=')
-            test_paths = g_slist_prepend (test_paths, equal + 1);
+            test_log_fd = g_ascii_strtoull (equal + 1, NULL, 0);
           else if (i + 1 < argc)
             {
               argv[i++] = NULL;
-              test_paths = g_slist_prepend (test_paths, argv[i]);
+              test_log_fd = g_ascii_strtoull (argv[i], NULL, 0);
             }
           argv[i] = NULL;
         }
-      else if (strcmp ("-o", argv[i]) == 0 || strncmp ("-o=", argv[i], 3) == 0)
+      else if (strcmp ("-p", argv[i]) == 0 || strncmp ("-p=", argv[i], 3) == 0)
         {
           gchar *equal = argv[i] + 2;
           if (*equal == '=')
-            test_run_output = equal + 1;
+            test_paths = g_slist_prepend (test_paths, equal + 1);
           else if (i + 1 < argc)
             {
               argv[i++] = NULL;
-              test_run_output = argv[i];
+              test_paths = g_slist_prepend (test_paths, argv[i]);
             }
           argv[i] = NULL;
         }
@@ -690,7 +696,7 @@ g_test_run_suite (GTestSuite *suite)
       rest = strchr (path, '/');
       l = strlen (path);
       l = rest ? MIN (l, rest - path) : l;
-      if (!l || l == n && strncmp (path, suite->name, n) == 0)
+      if ((!l || l == n) && strncmp (path, suite->name, n) == 0)
         n_bad += 0 != g_test_run_suite_internal (suite, rest ? rest : "");
     }
   return n_bad;
@@ -931,16 +937,15 @@ g_test_trap_fork (guint64        usec_timeout,
         close (stdout_pipe[1]);
       if (stderr_pipe[1] >= 3)
         close (stderr_pipe[1]);
-      test_stdmsg = stdtst_pipe[1];
+      test_log_fd = stdtst_pipe[1];
       return TRUE;
     }
   else                          /* parent */
     {
       GString *sout = g_string_new (NULL);
       GString *serr = g_string_new (NULL);
-      GString *stst = g_string_new (NULL);
       guint64 sstamp;
-      int soutpos = 0, serrpos = 0, ststpos = 0, wr, need_wait = TRUE;
+      int soutpos = 0, serrpos = 0, wr, need_wait = TRUE;
       test_run_forks++;
       close (stdout_pipe[1]);
       close (stderr_pipe[1]);
@@ -978,18 +983,24 @@ g_test_trap_fork (guint64        usec_timeout,
               close (stderr_pipe[0]);
               stderr_pipe[0] = -1;
             }
-          if (stdtst_pipe[0] >= 0 && FD_ISSET (stdtst_pipe[0], &fds) &&
-              g_string_must_read (stst, stdtst_pipe[0]) == 0)
+          if (stdtst_pipe[0] >= 0 && FD_ISSET (stdtst_pipe[0], &fds))
             {
-              close (stdtst_pipe[0]);
-              stdtst_pipe[0] = -1;
+              guint8 buffer[4096];
+              gint l, r = read (stdtst_pipe[0], buffer, sizeof (buffer));
+              if (r > 0 && test_log_fd > 0)
+                do
+                  l = write (test_log_fd, buffer, r);
+                while (l < 0 && errno == EINTR);
+              if (r == 0 || (r < 0 && errno != EINTR && errno != EAGAIN))
+                {
+                  close (stdtst_pipe[0]);
+                  stdtst_pipe[0] = -1;
+                }
             }
           if (!(test_trap_flags & G_TEST_TRAP_SILENCE_STDOUT))
             g_string_write_out (sout, 1, &soutpos);
           if (!(test_trap_flags & G_TEST_TRAP_SILENCE_STDERR))
             g_string_write_out (serr, 2, &serrpos);
-          if (TRUE) // FIXME: needs capturing into log file
-            g_string_write_out (stst, 1, &ststpos);
           if (usec_timeout)
             {
               guint64 nstamp = test_time_stamp();
@@ -1025,7 +1036,6 @@ g_test_trap_fork (guint64        usec_timeout,
         }
       test_trap_last_stdout = g_string_free (sout, FALSE);
       test_trap_last_stderr = g_string_free (serr, FALSE);
-      g_string_free (stst, TRUE);
       return FALSE;
     }
 }
index fa400f3e51849880364c88bfb2c2884affc4bff5..bdd3949f7d1263b309da45f988d815a7b4617e7c 100644 (file)
@@ -192,6 +192,7 @@ typedef struct {
   GSList      *msgs;
 } GTestLogBuffer;
 
+const char*     g_test_log_type_name    (GTestLogType    log_type);
 GTestLogBuffer* g_test_log_buffer_new   (void);
 void            g_test_log_buffer_free  (GTestLogBuffer *tbuffer);
 void            g_test_log_buffer_push  (GTestLogBuffer *tbuffer,