commit cb8ac1f33102dbe509edf50aa3cac2a106241466 Author: David Goulet dgoulet@torproject.org Date: Mon Jan 23 14:28:10 2017 -0500

trace: Add a basic event-tracing infrastructure.

This commit adds the src/trace directory containing the basics for our tracing subsystem. It is not used in the code base. The "src/trace/debug.h" file contains an example on how we can map our tor trace events to log_debug().

The tracing subsystem can only be enabled by tracing framework at compile time. This commit introduces the "--enable-tracing-debug" option that will make all "tor_trace()" function be maped to "log_debug()".

Closes #13802

Signed-off-by: David Goulet dgoulet@torproject.org --- .gitignore | 3 ++ changes/ticket13802 | 5 +++ configure.ac | 10 ++++++ doc/HACKING/Tracing.md | 90 ++++++++++++++++++++++++++++++++++++++++++++++++++ src/include.am | 1 + src/or/include.am | 1 + src/test/include.am | 5 +++ src/trace/debug.h | 25 ++++++++++++++ src/trace/events.h | 45 +++++++++++++++++++++++++ src/trace/include.am | 20 +++++++++++ 10 files changed, 205 insertions(+)

diff --git a/.gitignore b/.gitignore index f8d6e13..68bad5f 100644 --- a/.gitignore +++ b/.gitignore @@ -125,6 +125,9 @@ uptime-*.json /src/Makefile /src/Makefile.in

+# /src/trace +/src/trace/libor-trace.a + # /src/common/ /src/common/Makefile /src/common/Makefile.in diff --git a/changes/ticket13802 b/changes/ticket13802 new file mode 100644 index 0000000..581d5bd --- /dev/null +++ b/changes/ticket13802 @@ -0,0 +1,5 @@ + o Minor features (testing): + - Add general tracing instrumentation to Tor. For now, this subsystem is + not being used by any part of the code, it is for future use or external + testing that is not part of the upstream code base. Any tracing + framework needs to be enabled at compile time. Closes #13802. diff --git a/configure.ac b/configure.ac index c7960fa..ff91735 100644 --- a/configure.ac +++ b/configure.ac @@ -189,6 +189,16 @@ AC_ARG_ENABLE(seccomp, AC_ARG_ENABLE(libscrypt, AS_HELP_STRING(--disable-libscrypt, [do not attempt to use libscrypt]))

+dnl Enable event tracing which are transformed to debug log statement. +AC_ARG_ENABLE(event-tracing-debug, + AS_HELP_STRING(--enable-event-tracing-debug, [build with event tracing to debug log])) +AM_CONDITIONAL([USE_EVENT_TRACING_DEBUG], [test "x$enable_event_tracing_debug" = "xyes"]) + +if test x$enable_event_tracing_debug = xyes; then + AC_DEFINE([USE_EVENT_TRACING_DEBUG], [1], [Tracing framework to log debug]) + AC_DEFINE([TOR_EVENT_TRACING_ENABLED], [1], [Compile the event tracing instrumentation]) +fi + dnl check for the correct "ar" when cross-compiling. dnl (AM_PROG_AR was new in automake 1.11.2, which we do not yet require, dnl so kludge up a replacement for the case where it isn't there yet.) diff --git a/doc/HACKING/Tracing.md b/doc/HACKING/Tracing.md new file mode 100644 index 0000000..f4a55b7 --- /dev/null +++ b/doc/HACKING/Tracing.md @@ -0,0 +1,90 @@ +# Tracing # + +This document describes how the tracing subsystem works in tor so developers +can add events to the code base but also hook them to a tracing framework. + +## Basics ### + +Tracing is seperated in two concepts, trace events and a tracer. The tracing +subsystem can be found in `src/trace`. The `events.h` header file is the +main file that maps the different tracers to trace events. + +### Events ### + +A trace event is basically a function from which we can pass any data that +we want to collect. In addition, we specify a context for the event such as +a subsystem and an event name. + +A trace event in tor has the following standard format: + + tor_trace(subsystem, event_name, args...) + +The `subsystem` parameter is the name of the subsytem the trace event is in. +For example that could be "scheduler" or "vote" or "hs". The idea is to add +some context to the event so when we collect them we know where it's coming +from. The `event_name` is the name of the event which helps a lot with +adding some semantic to the event. Finally, `args` is any number of +arguments we want to collect. + +Here is an example of a possible tracepoint in main(): + + tor_trace(main, init_phase, argc) + +The above is a tracepoint in the `main` subsystem with `init_phase` as the +event name and the `int argc` is passed to the event as well. + +How `argc` is collected or used has nothing to do with the instrumentation +(adding trace events to the code). It is the work of the tracer so this is why +the trace events and collection framework (tracer) are decoupled. You _can_ +have trace events without a tracer. + +### Tracer ### + +In `src/trace/events.h`, we map the `tor_trace()` function to the right +tracer. A tracer support is only enabled at compile time. For instance, the +file `src/trace/debug.h` contains the mapping of the generic tracing function +`tor_trace()` to the `log_debug()` function. More specialized function can be +mapped depending on the tracepoint. + +## Build System ## + +This section describes how it is integrated into the build system of tor. + +By default, every tracing events are disabled in tor that is `tor_trace()` +is a NOP. + +To enable a tracer, there is a configure option on the form of: + + --enable-tracing-<tracer> + +We have an option that will send every trace events to a `log_debug()` (as +mentionned above) which will print you the subsystem and name of the event but +not the arguments for technical reasons. This is useful if you want to quickly +see if your trace event is being hit or well written. To do so, use this +configure option: + + --enable-tracing-debug + +## Instrument Tor ## + +This is pretty easy. Let's say you want to add a trace event in +`src/or/rendcache.c`, you only have to add this include statement: + + #include "trace/events.h" + +Once done, you can add as many as you want `tor_trace()` that you need. +Please use the right subsystem (here it would be `hs`) and a unique name that +tells what the event is for. For example: + + tor_trace(hs, store_desc_as_client, desc, desc_id); + +If you look in `src/trace/events.h`, you'll see that if tracing is enabled it +will be mapped to a function called: + + tor_trace_hs_store_desc_as_client(desc, desc_id) + +And the point of all this is for that function to be defined in a new file +that you might want to add named `src/trace/hs.{c|h}` which would defined how +to collect the data for the `tor_trace_hs_store_desc_as_client()` function +like for instance sending it to a `log_debug()` or do more complex operations +or use a userspace tracer like LTTng (https://lttng.org). diff --git a/src/include.am b/src/include.am index d12684e..f78853f 100644 --- a/src/include.am +++ b/src/include.am @@ -7,3 +7,4 @@ include src/tools/include.am include src/win32/include.am include src/config/include.am include src/test/fuzz/include.am +include src/trace/include.am diff --git a/src/or/include.am b/src/or/include.am index 483ea2f..4c24dd2 100644 --- a/src/or/include.am +++ b/src/or/include.am @@ -120,6 +120,7 @@ src_or_tor_LDFLAGS = @TOR_LDFLAGS_zlib@ @TOR_LDFLAGS_openssl@ @TOR_LDFLAGS_libev src_or_tor_LDADD = src/or/libtor.a src/common/libor.a src/common/libor-ctime.a \ src/common/libor-crypto.a $(LIBKECCAK_TINY) $(LIBDONNA) \ src/common/libor-event.a src/trunnel/libor-trunnel.a \ + src/trace/libor-trace.a \ @TOR_ZLIB_LIBS@ @TOR_LIB_MATH@ @TOR_LIBEVENT_LIBS@ @TOR_OPENSSL_LIBS@ \ @TOR_LIB_WS32@ @TOR_LIB_GDI@ @CURVE25519_LIBS@ @TOR_SYSTEMD_LIBS@ \ @TOR_LZMA_LIBS@ @TOR_ZSTD_LIBS@ diff --git a/src/test/include.am b/src/test/include.am index 653adad..230a6c8 100644 --- a/src/test/include.am +++ b/src/test/include.am @@ -193,6 +193,7 @@ src_test_test_LDADD = src/or/libtor-testing.a \ src/common/libor-ctime-testing.a \ src/common/libor-event-testing.a \ src/trunnel/libor-trunnel-testing.a \ + src/trace/libor-trace.a \ @TOR_ZLIB_LIBS@ @TOR_LIB_MATH@ @TOR_LIBEVENT_LIBS@ \ @TOR_OPENSSL_LIBS@ @TOR_LIB_WS32@ @TOR_LIB_GDI@ @CURVE25519_LIBS@ \ @TOR_SYSTEMD_LIBS@ @TOR_LZMA_LIBS@ @TOR_ZSTD_LIBS@ @@ -216,6 +217,7 @@ src_test_bench_LDADD = src/or/libtor.a src/common/libor.a \ src/common/libor-ctime.a \ src/common/libor-crypto.a $(LIBKECCAK_TINY) $(LIBDONNA) \ src/common/libor-event.a src/trunnel/libor-trunnel.a \ + src/trace/libor-trace.a \ @TOR_ZLIB_LIBS@ @TOR_LIB_MATH@ @TOR_LIBEVENT_LIBS@ \ @TOR_OPENSSL_LIBS@ @TOR_LIB_WS32@ @TOR_LIB_GDI@ @CURVE25519_LIBS@ \ @TOR_SYSTEMD_LIBS@ @TOR_LZMA_LIBS@ @TOR_ZSTD_LIBS@ @@ -227,6 +229,7 @@ src_test_test_workqueue_LDADD = src/or/libtor-testing.a \ src/common/libor-ctime-testing.a \ src/common/libor-crypto-testing.a $(LIBKECCAK_TINY) $(LIBDONNA) \ src/common/libor-event-testing.a \ + src/trace/libor-trace.a \ @TOR_ZLIB_LIBS@ @TOR_LIB_MATH@ @TOR_LIBEVENT_LIBS@ \ @TOR_OPENSSL_LIBS@ @TOR_LIB_WS32@ @TOR_LIB_GDI@ @CURVE25519_LIBS@ \ @TOR_LZMA_LIBS@ @TOR_ZSTD_LIBS@ @@ -264,6 +267,7 @@ src_test_test_ntor_cl_LDFLAGS = @TOR_LDFLAGS_zlib@ @TOR_LDFLAGS_openssl@ src_test_test_ntor_cl_LDADD = src/or/libtor.a src/common/libor.a \ src/common/libor-ctime.a \ src/common/libor-crypto.a $(LIBKECCAK_TINY) $(LIBDONNA) \ + src/trace/libor-trace.a \ @TOR_ZLIB_LIBS@ @TOR_LIB_MATH@ \ @TOR_OPENSSL_LIBS@ @TOR_LIB_WS32@ @TOR_LIB_GDI@ @CURVE25519_LIBS@ \ @TOR_LZMA_LIBS@ @@ -285,6 +289,7 @@ noinst_PROGRAMS += src/test/test-bt-cl src_test_test_bt_cl_SOURCES = src/test/test_bt_cl.c src_test_test_bt_cl_LDADD = src/common/libor-testing.a \ src/common/libor-ctime-testing.a \ + src/trace/libor-trace.a \ @TOR_LIB_MATH@ \ @TOR_LIB_WS32@ @TOR_LIB_GDI@ src_test_test_bt_cl_CFLAGS = $(AM_CFLAGS) $(TEST_CFLAGS) diff --git a/src/trace/debug.h b/src/trace/debug.h new file mode 100644 index 0000000..3a16525 --- /dev/null +++ b/src/trace/debug.h @@ -0,0 +1,25 @@ +/* Copyright (c) 2017, The Tor Project, Inc. */ +/* See LICENSE for licensing information */ + +#ifndef TOR_TRACE_LOG_DEBUG_H +#define TOR_TRACE_LOG_DEBUG_H + +#include "torlog.h" + +/* Stringify pre-processor trick. */ +#define XSTR(d) STR(d) +#define STR(s) #s + +/* Send every event to a debug log level. This is useful to debug new trace + * events without implementing them for a specific event tracing framework. + * Note that the arguments are ignored since at this step we do not know the + * types and amount there is. */ + +/* Example on how to map a tracepoint to log_debug(). */ +#undef tor_trace +#define tor_trace(subsystem, name, args...) \ + log_debug(LD_GENERAL, "Trace event "" XSTR(name) "" from " \ + """ XSTR(subsystem) "" hit. " \ + "(line "XSTR(__LINE__) ")") + +#endif /* TOR_TRACE_LOG_DEBUG_H */ diff --git a/src/trace/events.h b/src/trace/events.h new file mode 100644 index 0000000..1be1fd5 --- /dev/null +++ b/src/trace/events.h @@ -0,0 +1,45 @@ +/* Copyright (c) 2017, The Tor Project, Inc. */ +/* See LICENSE for licensing information */ + +/** + * \file events.h + * \brief Header file for Tor event tracing. + **/ + +#ifndef TOR_TRACE_EVENTS_H +#define TOR_TRACE_EVENTS_H + +/* + * The following defines a generic event tracing function name that has to be + * used to trace events in the code base. + * + * That generic function is then defined by a event tracing framework. For + * instance, the "log debug" framework sends all trace events to log_debug() + * which is defined in src/trace/debug.h which can only be enabled at compile + * time (--enable-event-tracing-debug). + * + * By default, every trace events in the code base are replaced by a NOP. See + * doc/HACKING/Tracing.md for more information on how to use event tracing or + * add events. + */ + +#ifdef TOR_EVENT_TRACING_ENABLED +/* Map every trace event to a per subsystem macro. */ +#define tor_trace(subsystem, name, ...) \ + tor_trace_##subsystem(name, __VA_ARGS__) + +/* Enable event tracing for the debug framework where all trace events are + * mapped to a log_debug(). */ +#ifdef USE_EVENT_TRACING_DEBUG +#include "trace/debug.h" +#endif + +#else /* TOR_EVENT_TRACING_ENABLED */ + +/* Reaching this point, we NOP every event declaration because event tracing + * is not been enabled at compile time. */ +#define tor_trace(subsystem, name, args...) + +#endif /* TOR_EVENT_TRACING_ENABLED */ + +#endif /* TOR_TRACE_EVENTS_H */ diff --git a/src/trace/include.am b/src/trace/include.am new file mode 100644 index 0000000..f7de1fb --- /dev/null +++ b/src/trace/include.am @@ -0,0 +1,20 @@ +# Include the src/ so we can use the trace/events.h statement when including +# any file in that directory. +AM_CPPFLAGS += -I$(srcdir)/src + +noinst_LIBRARIES += \ + src/trace/libor-trace.a +LIBOR_TRACE_A_SOURCES = + +TRACEHEADERS = \ + src/trace/events.h + +if USE_EVENT_TRACING_DEBUG +TRACEHEADERS += \ + src/trace/debug.h +endif + +# Library source files. +src_trace_libor_trace_a_SOURCES = $(LIBOR_TRACE_A_SOURCES) + +noinst_HEADERS+= $(TRACEHEADERS)