Merge pull request #2886 from jeffhostetler/jeffhostetler/clar_trace

Set up git_trace in clar test suite.

7 files changed, 325 insertions, 1 deletions

diff --git a/CMakeLists.txt b/CMakeLists.txt
index 81dc4c24a..c63107bf0 100644
--- a/CMakeLists.txt
+++ b/CMakeLists.txt
@@ -465,7 +465,7 @@ IF (BUILD_CLAR)
 
 	INCLUDE_DIRECTORIES(${CLAR_PATH})
 	FILE(GLOB_RECURSE SRC_TEST ${CLAR_PATH}/*/*.c ${CLAR_PATH}/*/*.h)
-	SET(SRC_CLAR "${CLAR_PATH}/main.c" "${CLAR_PATH}/clar_libgit2.c" "${CLAR_PATH}/clar.c")
+	SET(SRC_CLAR "${CLAR_PATH}/main.c" "${CLAR_PATH}/clar_libgit2.c" "${CLAR_PATH}/clar_libgit2_trace.c" "${CLAR_PATH}/clar_libgit2_timer.c" "${CLAR_PATH}/clar.c")
 
 	ADD_CUSTOM_COMMAND(
 		OUTPUT ${CLAR_PATH}/clar.suite
diff --git a/tests/clar_libgit2_timer.c b/tests/clar_libgit2_timer.c
new file mode 100644
index 000000000..737506da2
--- /dev/null
+++ b/tests/clar_libgit2_timer.c
@@ -0,0 +1,31 @@
+#include "clar_libgit2.h"
+#include "clar_libgit2_timer.h"
+#include "buffer.h"
+
+void cl_perf_timer__init(cl_perf_timer *t)
+{
+	memset(t, 0, sizeof(cl_perf_timer));
+}
+
+void cl_perf_timer__start(cl_perf_timer *t)
+{
+	t->time_started = git__timer();
+}
+
+void cl_perf_timer__stop(cl_perf_timer *t)
+{
+	double time_now = git__timer();
+
+	t->last = time_now - t->time_started;
+	t->sum += t->last;
+}
+
+double cl_perf_timer__last(const cl_perf_timer *t)
+{
+	return t->last;
+}
+
+double cl_perf_timer__sum(const cl_perf_timer *t)
+{
+	return t->sum;
+}
diff --git a/tests/clar_libgit2_timer.h b/tests/clar_libgit2_timer.h
new file mode 100644
index 000000000..0d150e018
--- /dev/null
+++ b/tests/clar_libgit2_timer.h
@@ -0,0 +1,35 @@
+#ifndef __CLAR_LIBGIT2_TIMER__
+#define __CLAR_LIBGIT2_TIMER__
+
+struct cl_perf_timer
+{
+	/* cummulative running time across all start..stop intervals */
+	double sum;
+
+	/* value of last start..stop interval */
+	double last;
+
+	/* clock value at start */
+	double time_started;
+};
+
+#define CL_PERF_TIMER_INIT {0}
+
+typedef struct cl_perf_timer cl_perf_timer;
+
+void cl_perf_timer__init(cl_perf_timer *t);
+void cl_perf_timer__start(cl_perf_timer *t);
+void cl_perf_timer__stop(cl_perf_timer *t);
+
+/**
+ * return value of last start..stop interval in seconds.
+ */
+double cl_perf_timer__last(const cl_perf_timer *t);
+
+/**
+ * return cummulative running time across all start..stop
+ * intervals in seconds.
+ */
+double cl_perf_timer__sum(const cl_perf_timer *t);
+
+#endif /* __CLAR_LIBGIT2_TIMER__ */
diff --git a/tests/clar_libgit2_trace.c b/tests/clar_libgit2_trace.c
new file mode 100644
index 000000000..ae582d1cb
--- /dev/null
+++ b/tests/clar_libgit2_trace.c
@@ -0,0 +1,229 @@
+#include "clar_libgit2.h"
+#include "clar_libgit2_trace.h"
+#include "clar_libgit2_timer.h"
+#include "trace.h"
+
+
+struct method {
+	const char *name;
+	void (*git_trace_cb)(git_trace_level_t level, const char *msg);
+	void (*close)(void);
+};
+
+
+#if defined(GIT_TRACE)
+static void _git_trace_cb__printf(git_trace_level_t level, const char *msg)
+{
+	/* TODO Use level to print a per-message prefix. */
+	GIT_UNUSED(level);
+
+	printf("%s\n", msg);
+}
+
+#if defined(GIT_WIN32)
+static void _git_trace_cb__debug(git_trace_level_t level, const char *msg)
+{
+	/* TODO Use level to print a per-message prefix. */
+	GIT_UNUSED(level);
+
+	OutputDebugString(msg);
+	OutputDebugString("\n");
+
+	printf("%s\n", msg);
+}
+#else
+#define _git_trace_cb__debug _git_trace_cb__printf
+#endif
+
+
+static void _trace_printf_close(void)
+{
+	fflush(stdout);
+}
+
+#define _trace_debug_close _trace_printf_close
+
+
+static struct method s_methods[] = {
+	{ "printf", _git_trace_cb__printf, _trace_printf_close },
+	{ "debug",  _git_trace_cb__debug,  _trace_debug_close  },
+	/* TODO add file method */
+	{0},
+};
+
+
+static int s_trace_loaded = 0;
+static int s_trace_level = GIT_TRACE_NONE;
+static struct method *s_trace_method = NULL;
+
+
+static int set_method(const char *name)
+{
+	int k;
+
+	if (!name || !*name)
+		name = "printf";
+
+	for (k=0; (s_methods[k].name); k++) {
+		if (strcmp(name, s_methods[k].name) == 0) {
+			s_trace_method = &s_methods[k];
+			return 0;
+		}
+	}
+	fprintf(stderr, "Unknown CLAR_TRACE_METHOD: '%s'\n", name);
+	return -1;
+}
+
+
+/**
+ * Lookup CLAR_TRACE_LEVEL and CLAR_TRACE_METHOD from
+ * the environment and set the above s_trace_* fields.
+ *
+ * If CLAR_TRACE_LEVEL is not set, we disable tracing.
+ *
+ * TODO If set, we assume GIT_TRACE_TRACE level, which
+ * logs everything. Later, we may want to parse the
+ * value of the environment variable and set a specific
+ * level.
+ *
+ * We assume the "printf" method.  This can be changed
+ * with the CLAR_TRACE_METHOD environment variable.
+ * Currently, this is only needed on Windows for a "debug"
+ * version which also writes to the debug output window
+ * in Visual Studio.
+ *
+ * TODO add a "file" method that would open and write
+ * to a well-known file. This would help keep trace
+ * output and clar output separate.
+ *
+ */
+static void _load_trace_params(void)
+{
+	char *sz_level;
+	char *sz_method;
+
+	s_trace_loaded = 1;
+
+	sz_level = cl_getenv("CLAR_TRACE_LEVEL");
+	if (!sz_level || !*sz_level) {
+		s_trace_level = GIT_TRACE_NONE;
+		s_trace_method = NULL;
+		return;
+	}
+
+	/* TODO Parse sz_level and set s_trace_level. */
+	s_trace_level = GIT_TRACE_TRACE;
+
+	sz_method = cl_getenv("CLAR_TRACE_METHOD");
+	if (set_method(sz_method) < 0)
+		set_method(NULL);
+}
+
+#define HR "================================================================"
+
+/**
+ * Timer to report the take spend in a test's run() method.
+ */
+static cl_perf_timer s_timer_run = CL_PERF_TIMER_INIT;
+
+/**
+ * Timer to report total time in a test (init, run, cleanup).
+ */
+static cl_perf_timer s_timer_test = CL_PERF_TIMER_INIT;
+
+void _cl_trace_cb__event_handler(
+	cl_trace_event ev,
+	const char *suite_name,
+	const char *test_name,
+	void *payload)
+{
+	GIT_UNUSED(payload);
+
+	switch (ev) {
+	case CL_TRACE__SUITE_BEGIN:
+		git_trace(GIT_TRACE_TRACE, "\n\n%s\n%s: Begin Suite", HR, suite_name);
+		break;
+
+	case CL_TRACE__SUITE_END:
+		git_trace(GIT_TRACE_TRACE, "\n\n%s: End Suite\n%s", suite_name, HR);
+		break;
+
+	case CL_TRACE__TEST__BEGIN:
+		git_trace(GIT_TRACE_TRACE, "\n%s::%s: Begin Test", suite_name, test_name);
+		cl_perf_timer__init(&s_timer_test);
+		cl_perf_timer__start(&s_timer_test);
+		break;
+
+	case CL_TRACE__TEST__END:
+		cl_perf_timer__stop(&s_timer_test);
+		git_trace(GIT_TRACE_TRACE, "%s::%s: End Test (%.3f %.3f)", suite_name, test_name,
+				  cl_perf_timer__last(&s_timer_run),
+				  cl_perf_timer__last(&s_timer_test));
+		break;
+
+	case CL_TRACE__TEST__RUN_BEGIN:
+		git_trace(GIT_TRACE_TRACE, "%s::%s: Begin Run", suite_name, test_name);
+		cl_perf_timer__init(&s_timer_run);
+		cl_perf_timer__start(&s_timer_run);
+		break;
+
+	case CL_TRACE__TEST__RUN_END:
+		cl_perf_timer__stop(&s_timer_run);
+		git_trace(GIT_TRACE_TRACE, "%s::%s: End Run", suite_name, test_name);
+		break;
+
+	case CL_TRACE__TEST__LONGJMP:
+		cl_perf_timer__stop(&s_timer_run);
+		git_trace(GIT_TRACE_TRACE, "%s::%s: Aborted", suite_name, test_name);
+		break;
+
+	default:
+		break;
+	}
+}
+
+#endif /*GIT_TRACE*/
+
+/**
+ * Setup/Enable git_trace() based upon settings user's environment.
+ *
+ */
+void cl_global_trace_register(void)
+{
+#if defined(GIT_TRACE)
+	if (!s_trace_loaded)
+		_load_trace_params();
+
+	if (s_trace_level == GIT_TRACE_NONE)
+		return;
+	if (s_trace_method == NULL)
+		return;
+	if (s_trace_method->git_trace_cb == NULL)
+		return;
+
+	git_trace_set(s_trace_level, s_trace_method->git_trace_cb);
+	cl_trace_register(_cl_trace_cb__event_handler, NULL);
+#endif
+}
+
+/**
+ * If we turned on git_trace() earlier, turn it off.
+ *
+ * This is intended to let us close/flush any buffered
+ * IO if necessary.
+ *
+ */
+void cl_global_trace_disable(void)
+{
+#if defined(GIT_TRACE)
+	cl_trace_register(NULL, NULL);
+	git_trace_set(GIT_TRACE_NONE, NULL);
+	if (s_trace_method && s_trace_method->close)
+		s_trace_method->close();
+
+	/* Leave s_trace_ vars set so they can restart tracing
+	 * since we only want to hit the environment variables
+	 * once.
+	 */
+#endif
+}
diff --git a/tests/clar_libgit2_trace.h b/tests/clar_libgit2_trace.h
new file mode 100644
index 000000000..09d1e050f
--- /dev/null
+++ b/tests/clar_libgit2_trace.h
@@ -0,0 +1,7 @@
+#ifndef __CLAR_LIBGIT2_TRACE__
+#define __CLAR_LIBGIT2_TRACE__
+
+void cl_global_trace_register(void);
+void cl_global_trace_disable(void);
+
+#endif
diff --git a/tests/main.c b/tests/main.c
index a092b8ba4..cc1323083 100644
--- a/tests/main.c
+++ b/tests/main.c
@@ -1,4 +1,5 @@
 #include "clar_libgit2.h"
+#include "clar_libgit2_trace.h"
 
 #ifdef _WIN32
 int __cdecl main(int argc, char *argv[])
@@ -11,6 +12,7 @@ int main(int argc, char *argv[])
 	clar_test_init(argc, argv);
 
 	git_libgit2_init();
+	cl_global_trace_register();
 	cl_sandbox_set_search_path_defaults();
 
 	/* Run the test suite */
@@ -19,6 +21,7 @@ int main(int argc, char *argv[])
 	clar_test_shutdown();
 
 	giterr_clear();
+	cl_global_trace_disable();
 	git_libgit2_shutdown();
 
 	return res;
diff --git a/tests/trace/trace.c b/tests/trace/trace.c
index 87b325378..097208bff 100644
--- a/tests/trace/trace.c
+++ b/tests/trace/trace.c
@@ -1,4 +1,5 @@
 #include "clar_libgit2.h"
+#include "clar_libgit2_trace.h"
 #include "trace.h"
 
 static int written = 0;
@@ -14,6 +15,9 @@ static void trace_callback(git_trace_level_t level, const char *message)
 
 void test_trace_trace__initialize(void)
 {
+	/* If global tracing is enabled, disable for the duration of this test. */
+	cl_global_trace_disable();
+
 	git_trace_set(GIT_TRACE_INFO, trace_callback);
 	written = 0;
 }
@@ -21,12 +25,17 @@ void test_trace_trace__initialize(void)
 void test_trace_trace__cleanup(void)
 {
 	git_trace_set(GIT_TRACE_NONE, NULL);
+
+	/* If global tracing was enabled, restart it. */
+	cl_global_trace_register();
 }
 
 void test_trace_trace__sets(void)
 {
 #ifdef GIT_TRACE
 	cl_assert(git_trace_level() == GIT_TRACE_INFO);
+#else
+	cl_skip();
 #endif
 }
 
@@ -42,6 +51,8 @@ void test_trace_trace__can_reset(void)
 
 	git_trace(GIT_TRACE_ERROR, "Hello %s!", "world");
 	cl_assert(written == 1);
+#else
+	cl_skip();
 #endif
 }
 
@@ -56,6 +67,8 @@ void test_trace_trace__can_unset(void)
 	cl_assert(written == 0);
 	git_trace(GIT_TRACE_FATAL, "Hello %s!", "world");
 	cl_assert(written == 0);
+#else
+	cl_skip();
 #endif
 }
 
@@ -65,6 +78,8 @@ void test_trace_trace__skips_higher_level(void)
 	cl_assert(written == 0);
 	git_trace(GIT_TRACE_DEBUG, "Hello %s!", "world");
 	cl_assert(written == 0);
+#else
+	cl_skip();
 #endif
 }
 
@@ -74,6 +89,8 @@ void test_trace_trace__writes(void)
 	cl_assert(written == 0);
 	git_trace(GIT_TRACE_INFO, "Hello %s!", "world");
 	cl_assert(written == 1);
+#else
+	cl_skip();
 #endif
 }
 
@@ -83,5 +100,7 @@ void test_trace_trace__writes_lower_level(void)
 	cl_assert(written == 0);
 	git_trace(GIT_TRACE_ERROR, "Hello %s!", "world");
 	cl_assert(written == 1);
+#else
+	cl_skip();
 #endif
 }