[libgit2.git] / tests / clar_libgit2_trace.c

#include "clar_libgit2_trace.h"
#include "clar_libgit2.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);
};

static const char *message_prefix(git_trace_level_t level)
{
	switch (level) {
	case GIT_TRACE_NONE:
		return "[NONE]:  ";
	case GIT_TRACE_FATAL:
		return "[FATAL]: ";
	case GIT_TRACE_ERROR:
		return "[ERROR]: ";
	case GIT_TRACE_WARN:
		return "[WARN]:  ";
	case GIT_TRACE_INFO:
		return "[INFO]:  ";
	case GIT_TRACE_DEBUG:
		return "[DEBUG]: ";
	case GIT_TRACE_TRACE:
		return "[TRACE]: ";
	default:
		return "[?????]: ";
	}
}

static void _git_trace_cb__printf(git_trace_level_t level, const char *msg)
{
	printf("%s%s\n", message_prefix(level), msg);
}

#if defined(GIT_WIN32)
static void _git_trace_cb__debug(git_trace_level_t level, const char *msg)
{
	OutputDebugString(message_prefix(level));
	OutputDebugString(msg);
	OutputDebugString("\n");

	printf("%s%s\n", message_prefix(level), 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 s_trace_tests = 0;

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;
	char *sz_tests;

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

	sz_tests = cl_getenv("CLAR_TRACE_TESTS");
	if (sz_tests != NULL)
		s_trace_tests = 1;
}

#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;

static void _cl_trace_cb__event_handler(
	cl_trace_event ev,
	const char *suite_name,
	const char *test_name,
	void *payload)
{
	GIT_UNUSED(payload);

	if (!s_trace_tests)
		return;

	switch (ev) {
	case CL_TRACE__SUITE_BEGIN:
		git_trace(GIT_TRACE_TRACE, "\n\n%s\n%s: Begin Suite", HR, suite_name);
#if 0 && defined(GIT_WIN32_LEAKCHECK)
		git_win32__crtdbg_stacktrace__dump(
			GIT_WIN32__CRTDBG_STACKTRACE__SET_MARK,
			suite_name);
#endif
		break;

	case CL_TRACE__SUITE_END:
#if 0 && defined(GIT_WIN32_LEAKCHECK)
		/* As an example of checkpointing, dump leaks within this suite.
		 * This may generate false positives for things like the global
		 * TLS error state and maybe the odb cache since they aren't
		 * freed until the global shutdown and outside the scope of this
		 * set of tests.
		 *
		 * This may under-report if the test itself uses a checkpoint.
		 * See tests/trace/windows/stacktrace.c
		 */
		git_win32__crtdbg_stacktrace__dump(
			GIT_WIN32__CRTDBG_STACKTRACE__LEAKS_SINCE_MARK,
			suite_name);
#endif
		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;
	}
}

/**
 * Setup/Enable git_trace() based upon settings user's environment.
 */
void cl_global_trace_register(void)
{
	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);
}

/**
 * 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)
{
	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.
	 */
}
Commit	Line	Data
6b5c0886	1	#include "clar_libgit2_trace.h"
22a2d3d5	2	#include "clar_libgit2.h"
9a859ef5	3	#include "clar_libgit2_timer.h"
6b5c0886 JH	4	#include "trace.h"
6b5c0886 JH	5
6b5c0886 JH	6	struct method {
	7	const char *name;
	8	void (git_trace_cb)(git_trace_level_t level, const char msg);
	9	void (*close)(void);
	10	};
	11
22a2d3d5 UG	12	static const char *message_prefix(git_trace_level_t level)
	13	{
	14	switch (level) {
	15	case GIT_TRACE_NONE:
	16	return "[NONE]: ";
	17	case GIT_TRACE_FATAL:
	18	return "[FATAL]: ";
	19	case GIT_TRACE_ERROR:
	20	return "[ERROR]: ";
	21	case GIT_TRACE_WARN:
	22	return "[WARN]: ";
	23	case GIT_TRACE_INFO:
	24	return "[INFO]: ";
	25	case GIT_TRACE_DEBUG:
	26	return "[DEBUG]: ";
	27	case GIT_TRACE_TRACE:
	28	return "[TRACE]: ";
	29	default:
	30	return "[?????]: ";
	31	}
	32	}
6b5c0886	33
6b5c0886 JH	34	static void _git_trace_cb__printf(git_trace_level_t level, const char *msg)
6b5c0886 JH	35	{
22a2d3d5	36	printf("%s%s\n", message_prefix(level), msg);
6b5c0886 JH	37	}
	38
	39	#if defined(GIT_WIN32)
	40	static void _git_trace_cb__debug(git_trace_level_t level, const char *msg)
	41	{
22a2d3d5	42	OutputDebugString(message_prefix(level));
6b5c0886 JH	43	OutputDebugString(msg);
	44	OutputDebugString("\n");
	45
22a2d3d5	46	printf("%s%s\n", message_prefix(level), msg);
6b5c0886 JH	47	}
	48	#else
	49	#define _git_trace_cb__debug _git_trace_cb__printf
	50	#endif
	51
	52
	53	static void _trace_printf_close(void)
	54	{
	55	fflush(stdout);
	56	}
	57
	58	#define _trace_debug_close _trace_printf_close
	59
	60
	61	static struct method s_methods[] = {
	62	{ "printf", _git_trace_cb__printf, _trace_printf_close },
	63	{ "debug", _git_trace_cb__debug, _trace_debug_close },
	64	/* TODO add file method */
	65	{0},
	66	};
	67
	68
	69	static int s_trace_loaded = 0;
	70	static int s_trace_level = GIT_TRACE_NONE;
	71	static struct method *s_trace_method = NULL;
22a2d3d5	72	static int s_trace_tests = 0;
6b5c0886 JH	73
	74	static int set_method(const char *name)
	75	{
	76	int k;
	77
	78	if (!name \|\| !*name)
	79	name = "printf";
	80
	81	for (k=0; (s_methods[k].name); k++) {
	82	if (strcmp(name, s_methods[k].name) == 0) {
	83	s_trace_method = &s_methods[k];
	84	return 0;
	85	}
	86	}
	87	fprintf(stderr, "Unknown CLAR_TRACE_METHOD: '%s'\n", name);
	88	return -1;
	89	}
	90
	91
	92	/**
	93	* Lookup CLAR_TRACE_LEVEL and CLAR_TRACE_METHOD from
	94	* the environment and set the above s_trace_* fields.
	95	*
	96	* If CLAR_TRACE_LEVEL is not set, we disable tracing.
	97	*
	98	* TODO If set, we assume GIT_TRACE_TRACE level, which
	99	* logs everything. Later, we may want to parse the
	100	* value of the environment variable and set a specific
	101	* level.
	102	*
	103	* We assume the "printf" method. This can be changed
	104	* with the CLAR_TRACE_METHOD environment variable.
	105	* Currently, this is only needed on Windows for a "debug"
	106	* version which also writes to the debug output window
	107	* in Visual Studio.
	108	*
	109	* TODO add a "file" method that would open and write
	110	* to a well-known file. This would help keep trace
	111	* output and clar output separate.
	112	*
	113	*/
	114	static void _load_trace_params(void)
	115	{
	116	char *sz_level;
	117	char *sz_method;
22a2d3d5	118	char *sz_tests;
6b5c0886 JH	119
	120	s_trace_loaded = 1;
	121
	122	sz_level = cl_getenv("CLAR_TRACE_LEVEL");
	123	if (!sz_level \|\| !*sz_level) {
	124	s_trace_level = GIT_TRACE_NONE;
	125	s_trace_method = NULL;
	126	return;
	127	}
	128
	129	/* TODO Parse sz_level and set s_trace_level. */
	130	s_trace_level = GIT_TRACE_TRACE;
	131
	132	sz_method = cl_getenv("CLAR_TRACE_METHOD");
	133	if (set_method(sz_method) < 0)
	134	set_method(NULL);
22a2d3d5 UG	135
	136	sz_tests = cl_getenv("CLAR_TRACE_TESTS");
	137	if (sz_tests != NULL)
	138	s_trace_tests = 1;
6b5c0886 JH	139	}
	140
	141	#define HR "================================================================"
	142
9a859ef5 JH	143	/**
	144	* Timer to report the take spend in a test's run() method.
	145	*/
	146	static cl_perf_timer s_timer_run = CL_PERF_TIMER_INIT;
	147
	148	/**
	149	* Timer to report total time in a test (init, run, cleanup).
	150	*/
	151	static cl_perf_timer s_timer_test = CL_PERF_TIMER_INIT;
	152
e579e0f7	153	static void _cl_trace_cb__event_handler(
6b5c0886 JH	154	cl_trace_event ev,
	155	const char *suite_name,
	156	const char *test_name,
	157	void *payload)
	158	{
	159	GIT_UNUSED(payload);
	160
22a2d3d5 UG	161	if (!s_trace_tests)
	162	return;
	163
6b5c0886 JH	164	switch (ev) {
6b5c0886 JH	165	case CL_TRACE__SUITE_BEGIN:
f096fbf4	166	git_trace(GIT_TRACE_TRACE, "\n\n%s\n%s: Begin Suite", HR, suite_name);
c25aa7cd	167	#if 0 && defined(GIT_WIN32_LEAKCHECK)
93b42728 JH	168	git_win32__crtdbg_stacktrace__dump(
	169	GIT_WIN32__CRTDBG_STACKTRACE__SET_MARK,
	170	suite_name);
	171	#endif
6b5c0886 JH	172	break;
	173
	174	case CL_TRACE__SUITE_END:
c25aa7cd	175	#if 0 && defined(GIT_WIN32_LEAKCHECK)
93b42728 JH	176	/* As an example of checkpointing, dump leaks within this suite.
	177	* This may generate false positives for things like the global
	178	* TLS error state and maybe the odb cache since they aren't
	179	* freed until the global shutdown and outside the scope of this
	180	* set of tests.
	181	*
	182	* This may under-report if the test itself uses a checkpoint.
	183	* See tests/trace/windows/stacktrace.c
	184	*/
	185	git_win32__crtdbg_stacktrace__dump(
	186	GIT_WIN32__CRTDBG_STACKTRACE__LEAKS_SINCE_MARK,
	187	suite_name);
	188	#endif
f096fbf4	189	git_trace(GIT_TRACE_TRACE, "\n\n%s: End Suite\n%s", suite_name, HR);
6b5c0886 JH	190	break;
	191
	192	case CL_TRACE__TEST__BEGIN:
f096fbf4	193	git_trace(GIT_TRACE_TRACE, "\n%s::%s: Begin Test", suite_name, test_name);
9a859ef5 JH	194	cl_perf_timer__init(&s_timer_test);
9a859ef5 JH	195	cl_perf_timer__start(&s_timer_test);
6b5c0886 JH	196	break;
	197
	198	case CL_TRACE__TEST__END:
9a859ef5 JH	199	cl_perf_timer__stop(&s_timer_test);
	200	git_trace(GIT_TRACE_TRACE, "%s::%s: End Test (%.3f %.3f)", suite_name, test_name,
	201	cl_perf_timer__last(&s_timer_run),
	202	cl_perf_timer__last(&s_timer_test));
6b5c0886 JH	203	break;
	204
	205	case CL_TRACE__TEST__RUN_BEGIN:
f096fbf4	206	git_trace(GIT_TRACE_TRACE, "%s::%s: Begin Run", suite_name, test_name);
9a859ef5 JH	207	cl_perf_timer__init(&s_timer_run);
9a859ef5 JH	208	cl_perf_timer__start(&s_timer_run);
6b5c0886 JH	209	break;
	210
	211	case CL_TRACE__TEST__RUN_END:
9a859ef5	212	cl_perf_timer__stop(&s_timer_run);
f096fbf4	213	git_trace(GIT_TRACE_TRACE, "%s::%s: End Run", suite_name, test_name);
6b5c0886 JH	214	break;
	215
	216	case CL_TRACE__TEST__LONGJMP:
9a859ef5	217	cl_perf_timer__stop(&s_timer_run);
f096fbf4	218	git_trace(GIT_TRACE_TRACE, "%s::%s: Aborted", suite_name, test_name);
6b5c0886 JH	219	break;
	220
	221	default:
	222	break;
	223	}
	224	}
	225
6b5c0886 JH	226	/**
6b5c0886 JH	227	* Setup/Enable git_trace() based upon settings user's environment.
6b5c0886 JH	228	*/
	229	void cl_global_trace_register(void)
	230	{
6b5c0886 JH	231	if (!s_trace_loaded)
	232	_load_trace_params();
	233
	234	if (s_trace_level == GIT_TRACE_NONE)
	235	return;
	236	if (s_trace_method == NULL)
	237	return;
	238	if (s_trace_method->git_trace_cb == NULL)
	239	return;
	240
	241	git_trace_set(s_trace_level, s_trace_method->git_trace_cb);
	242	cl_trace_register(_cl_trace_cb__event_handler, NULL);
6b5c0886 JH	243	}
	244
	245	/**
	246	* If we turned on git_trace() earlier, turn it off.
	247	*
	248	* This is intended to let us close/flush any buffered
	249	* IO if necessary.
	250	*
	251	*/
	252	void cl_global_trace_disable(void)
	253	{
6b5c0886 JH	254	cl_trace_register(NULL, NULL);
	255	git_trace_set(GIT_TRACE_NONE, NULL);
	256	if (s_trace_method && s_trace_method->close)
	257	s_trace_method->close();
	258
	259	/* Leave s_trace_ vars set so they can restart tracing
	260	* since we only want to hit the environment variables
	261	* once.
	262	*/
6b5c0886	263	}