From 22ac72234a8ce3f543848d8a7508b95115dc75a7 Mon Sep 17 00:00:00 2001 From: Tim Janik Date: Tue, 20 Nov 2007 15:00:45 +0000 Subject: [PATCH] Implemented test log IPC. * 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= if given, removed bogus -o-option. svn path=/trunk/; revision=5898 --- glib/gtester.c | 134 ++++++++++++++++++++++++++++++++++++++------------ glib/gtestframework.c | 58 +++++++++++++--------- glib/gtestframework.h | 1 + 3 files changed, 137 insertions(+), 56 deletions(-) diff --git a/glib/gtester.c b/glib/gtester.c index db60ee0..1deb9a5 100644 --- a/glib/gtester.c +++ b/glib/gtester.c @@ -21,6 +21,10 @@ #include #include #include +#include +#include +#include +#include /* 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 @@ -95,17 +122,42 @@ queue_gfree (GSList **slistp, } 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); diff --git a/glib/gtestframework.c b/glib/gtestframework.c index 30e70dd..a459f9a 100644 --- a/glib/gtestframework.c +++ b/glib/gtestframework.c @@ -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; } } diff --git a/glib/gtestframework.h b/glib/gtestframework.h index fa400f3..bdd3949 100644 --- a/glib/gtestframework.h +++ b/glib/gtestframework.h @@ -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, -- 2.7.4