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=<fd> if given, removed
bogus -o-option.

svn path=/trunk/; revision=5898
This commit is contained in:
Tim Janik 2007-11-20 15:00:45 +00:00
parent add119f8e1
commit 22ac72234a
3 changed files with 142 additions and 61 deletions

View File

@ -21,6 +21,10 @@
#include <string.h> #include <string.h>
#include <stdlib.h> #include <stdlib.h>
#include <unistd.h> #include <unistd.h>
#include <unistd.h>
#include <fcntl.h>
#include <errno.h>
#include <signal.h>
/* the read buffer size in bytes */ /* the read buffer size in bytes */
#define READ_BUFFER_SIZE 4096 #define READ_BUFFER_SIZE 4096
@ -33,7 +37,7 @@ static void parse_args (gint *argc_p,
static GIOChannel *ioc_report = NULL; static GIOChannel *ioc_report = NULL;
static gboolean subtest_running = FALSE; static gboolean subtest_running = FALSE;
static gboolean subtest_io_pending = 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_verbose = FALSE;
static gboolean gtester_list_tests = FALSE; static gboolean gtester_list_tests = FALSE;
static gboolean subtest_mode_fatal = FALSE; static gboolean subtest_mode_fatal = FALSE;
@ -49,32 +53,55 @@ child_report_cb (GIOChannel *source,
GIOCondition condition, GIOCondition condition,
gpointer data) gpointer data)
{ {
GTestLogBuffer *tlb = data;
GIOStatus status = G_IO_STATUS_NORMAL; GIOStatus status = G_IO_STATUS_NORMAL;
gsize length = 0;
while (status == G_IO_STATUS_NORMAL) do
{ {
gchar buffer[READ_BUFFER_SIZE]; guint8 buffer[READ_BUFFER_SIZE];
gsize length = 0;
GError *error = NULL; GError *error = NULL;
status = g_io_channel_read_chars (source, buffer, sizeof (buffer), &length, &error); status = g_io_channel_read_chars (source, (gchar*) buffer, sizeof (buffer), &length, &error);
switch (status) if (length)
{ {
case G_IO_STATUS_NORMAL: GTestLogMsg *msg;
write (2, buffer, length); /* passthrough child's stdout */ g_test_log_buffer_push (tlb, length, buffer);
break; do
case G_IO_STATUS_AGAIN: {
/* retry later */ msg = g_test_log_buffer_pop (tlb);
break; if (msg)
case G_IO_STATUS_ERROR: {
/* ignore, child closed fd or similar g_warning ("Error while reading data: %s", error->message); */ guint ui;
/* fall through into EOF */ /* print message, this should be written to an XML log file */
case G_IO_STATUS_EOF: g_printerr ("{*GTLOG(%s)", g_test_log_type_name (msg->log_type));
subtest_io_pending = FALSE; for (ui = 0; ui < msg->n_strings; ui++)
return FALSE; 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); 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 static void
@ -94,18 +121,43 @@ queue_gfree (GSList **slistp,
return string; 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 static void
launch_test (const char *binary) launch_test (const char *binary)
{ {
GTestLogBuffer *tlb;
GSList *slist, *free_list = NULL; GSList *slist, *free_list = NULL;
GError *error = NULL; GError *error = NULL;
const gchar *argv[20 + g_slist_length (subtest_paths)]; const gchar *argv[20 + g_slist_length (subtest_paths)];
GPid pid = 0; 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 */ /* setup argv */
argv[i++] = binary; 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) if (!subtest_mode_fatal)
argv[i++] = "--keep-going"; argv[i++] = "--keep-going";
if (subtest_mode_quick) if (subtest_mode_quick)
@ -122,26 +174,24 @@ launch_test (const char *binary)
argv[i++] = "-l"; argv[i++] = "-l";
argv[i++] = NULL; 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() */ g_spawn_async_with_pipes (NULL, /* g_get_current_dir() */
(gchar**) argv, (gchar**) argv,
NULL, /* envp */ NULL, /* envp */
G_SPAWN_DO_NOT_REAP_CHILD, /* G_SPAWN_SEARCH_PATH */ 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, &pid,
NULL, /* standard_input */ NULL, /* standard_input */
&child_report, /* standard_output */ NULL, /* standard_output */
NULL, /* standard_error */ NULL, /* standard_error */
&error); &error);
g_slist_foreach (free_list, (void(*)(void*,void*)) g_free, NULL); g_slist_foreach (free_list, (void(*)(void*,void*)) g_free, NULL);
g_slist_free (free_list); g_slist_free (free_list);
free_list = NULL; free_list = NULL;
close (report_pipe[1]);
if (error) if (error)
{ {
close (report_pipe[0]);
if (subtest_mode_fatal) if (subtest_mode_fatal)
g_error ("Failed to execute test binary: %s: %s", argv[0], error->message); g_error ("Failed to execute test binary: %s: %s", argv[0], error->message);
else else
@ -149,14 +199,17 @@ launch_test (const char *binary)
g_clear_error (&error); g_clear_error (&error);
return; return;
} }
subtest_running = TRUE; subtest_running = TRUE;
subtest_io_pending = TRUE; subtest_io_pending = TRUE;
tlb = g_test_log_buffer_new();
if (child_report >= 0) 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_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_io_channel_unref (ioc_report);
} }
g_child_watch_add_full (G_PRIORITY_DEFAULT + 1, pid, child_watch_cb, NULL, NULL); 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 */ subtest_io_pending || /* FALSE once ioc_report closes */
g_main_context_pending (NULL)) /* TRUE while idler, etc are running */ g_main_context_pending (NULL)) /* TRUE while idler, etc are running */
g_main_context_iteration (NULL, TRUE); g_main_context_iteration (NULL, TRUE);
close (report_pipe[0]);
g_test_log_buffer_free (tlb);
} }
static void static void
@ -322,6 +378,20 @@ main (int argc,
{ {
guint ui; 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]); g_set_prgname (argv[0]);
parse_args (&argc, &argv); parse_args (&argc, &argv);

View File

@ -53,7 +53,7 @@ static guint8* g_test_log_dump (GTestLogMsg *msg,
guint *len); guint *len);
/* --- variables --- */ /* --- variables --- */
static int test_stdmsg = 1; static int test_log_fd = -1;
static gboolean test_mode_quick = TRUE; static gboolean test_mode_quick = TRUE;
static gboolean test_mode_perf = FALSE; static gboolean test_mode_perf = FALSE;
static gboolean test_mode_fatal = TRUE; 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_quiet = FALSE;
static gboolean test_run_verbose = FALSE; static gboolean test_run_verbose = FALSE;
static gboolean test_run_list = FALSE; static gboolean test_run_list = FALSE;
static gchar *test_run_output = NULL;
static gchar *test_run_seedstr = NULL; static gchar *test_run_seedstr = NULL;
static GRand *test_run_rand = NULL; static GRand *test_run_rand = NULL;
static gchar *test_run_name = ""; static gchar *test_run_name = "";
@ -79,10 +78,10 @@ static char *test_trap_last_stderr = NULL;
static gboolean test_debug_log = FALSE; static gboolean test_debug_log = FALSE;
/* --- functions --- */ /* --- functions --- */
static const char* const char*
test_log_bit (GTestLogType lbit) 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_START_BINARY: return "binary";
case G_TEST_LOG_LIST_CASE: return "list"; case G_TEST_LOG_LIST_CASE: return "list";
@ -98,6 +97,13 @@ static void
g_test_log_send (guint n_bytes, g_test_log_send (guint n_bytes,
const guint8 *buffer) 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) if (test_debug_log)
{ {
GTestLogBuffer *lbuffer = g_test_log_buffer_new(); 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_assert (lbuffer->data->len == 0); // FIXME: should be g_awrn_if_fail
g_test_log_buffer_free (lbuffer); g_test_log_buffer_free (lbuffer);
/* print message */ /* 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++) for (ui = 0; ui < msg->n_strings; ui++)
g_printerr (":{%s}", msg->strings[ui]); g_printerr (":{%s}", msg->strings[ui]);
if (msg->n_nums) if (msg->n_nums)
@ -205,6 +211,18 @@ parse_args (gint *argc_p,
test_debug_log = TRUE; test_debug_log = TRUE;
argv[i] = NULL; argv[i] = NULL;
} }
else if (strcmp ("--GTestLogFD", argv[i]) == 0 || strncmp ("--GTestLogFD=", argv[i], 13) == 0)
{
gchar *equal = argv[i] + 12;
if (*equal == '=')
test_log_fd = g_ascii_strtoull (equal + 1, NULL, 0);
else if (i + 1 < argc)
{
argv[i++] = NULL;
test_log_fd = g_ascii_strtoull (argv[i], NULL, 0);
}
argv[i] = NULL;
}
else if (strcmp ("-p", argv[i]) == 0 || strncmp ("-p=", argv[i], 3) == 0) else if (strcmp ("-p", argv[i]) == 0 || strncmp ("-p=", argv[i], 3) == 0)
{ {
gchar *equal = argv[i] + 2; gchar *equal = argv[i] + 2;
@ -217,18 +235,6 @@ parse_args (gint *argc_p,
} }
argv[i] = NULL; argv[i] = NULL;
} }
else if (strcmp ("-o", argv[i]) == 0 || strncmp ("-o=", argv[i], 3) == 0)
{
gchar *equal = argv[i] + 2;
if (*equal == '=')
test_run_output = equal + 1;
else if (i + 1 < argc)
{
argv[i++] = NULL;
test_run_output = argv[i];
}
argv[i] = NULL;
}
else if (strcmp ("-m", argv[i]) == 0 || strncmp ("-m=", argv[i], 3) == 0) else if (strcmp ("-m", argv[i]) == 0 || strncmp ("-m=", argv[i], 3) == 0)
{ {
gchar *equal = argv[i] + 2; gchar *equal = argv[i] + 2;
@ -690,7 +696,7 @@ g_test_run_suite (GTestSuite *suite)
rest = strchr (path, '/'); rest = strchr (path, '/');
l = strlen (path); l = strlen (path);
l = rest ? MIN (l, rest - path) : l; 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 : ""); n_bad += 0 != g_test_run_suite_internal (suite, rest ? rest : "");
} }
return n_bad; return n_bad;
@ -931,16 +937,15 @@ g_test_trap_fork (guint64 usec_timeout,
close (stdout_pipe[1]); close (stdout_pipe[1]);
if (stderr_pipe[1] >= 3) if (stderr_pipe[1] >= 3)
close (stderr_pipe[1]); close (stderr_pipe[1]);
test_stdmsg = stdtst_pipe[1]; test_log_fd = stdtst_pipe[1];
return TRUE; return TRUE;
} }
else /* parent */ else /* parent */
{ {
GString *sout = g_string_new (NULL); GString *sout = g_string_new (NULL);
GString *serr = g_string_new (NULL); GString *serr = g_string_new (NULL);
GString *stst = g_string_new (NULL);
guint64 sstamp; 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++; test_run_forks++;
close (stdout_pipe[1]); close (stdout_pipe[1]);
close (stderr_pipe[1]); close (stderr_pipe[1]);
@ -978,18 +983,24 @@ g_test_trap_fork (guint64 usec_timeout,
close (stderr_pipe[0]); close (stderr_pipe[0]);
stderr_pipe[0] = -1; stderr_pipe[0] = -1;
} }
if (stdtst_pipe[0] >= 0 && FD_ISSET (stdtst_pipe[0], &fds) && if (stdtst_pipe[0] >= 0 && FD_ISSET (stdtst_pipe[0], &fds))
g_string_must_read (stst, stdtst_pipe[0]) == 0)
{ {
close (stdtst_pipe[0]); guint8 buffer[4096];
stdtst_pipe[0] = -1; 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)) if (!(test_trap_flags & G_TEST_TRAP_SILENCE_STDOUT))
g_string_write_out (sout, 1, &soutpos); g_string_write_out (sout, 1, &soutpos);
if (!(test_trap_flags & G_TEST_TRAP_SILENCE_STDERR)) if (!(test_trap_flags & G_TEST_TRAP_SILENCE_STDERR))
g_string_write_out (serr, 2, &serrpos); 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) if (usec_timeout)
{ {
guint64 nstamp = test_time_stamp(); 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_stdout = g_string_free (sout, FALSE);
test_trap_last_stderr = g_string_free (serr, FALSE); test_trap_last_stderr = g_string_free (serr, FALSE);
g_string_free (stst, TRUE);
return FALSE; return FALSE;
} }
} }

View File

@ -192,6 +192,7 @@ typedef struct {
GSList *msgs; GSList *msgs;
} GTestLogBuffer; } GTestLogBuffer;
const char* g_test_log_type_name (GTestLogType log_type);
GTestLogBuffer* g_test_log_buffer_new (void); GTestLogBuffer* g_test_log_buffer_new (void);
void g_test_log_buffer_free (GTestLogBuffer *tbuffer); void g_test_log_buffer_free (GTestLogBuffer *tbuffer);
void g_test_log_buffer_push (GTestLogBuffer *tbuffer, void g_test_log_buffer_push (GTestLogBuffer *tbuffer,