Add execution trace option for debugging.

Use `cmake -DEXECUTION_TRACE=ON` to use it.

3 files changed, 217 insertions, 3 deletions

diff --git a/CMakeLists.txt b/CMakeLists.txt
index f108e2b1..73f66cf1 100644
--- a/CMakeLists.txt
+++ b/CMakeLists.txt
@@ -82,6 +82,11 @@ else()
   message(STATUS "Supported C++ compiler features = ${CMAKE_CXX_COMPILE_FEATURES}")
 endif()
 
+option(EXECUTION_TRACE "Print a function trace during execution (for debugging)" OFF)
+if(EXECUTION_TRACE)
+  set(CMAKE_C_FLAGS "${CMAKE_C_FLAGS} -finstrument-functions")
+endif()
+
 set(MIN_LOGGER_LEVEL "" CACHE STRING "Logging level to use (TRACE, DEBUG, INFO, WARNING, ERROR)")
 if(MIN_LOGGER_LEVEL)
   if(("${MIN_LOGGER_LEVEL}" STREQUAL "TRACE") OR
@@ -360,9 +365,14 @@ unit_test(toxcore util)
 #
 ################################################################################
 
-add_library(misc_tools
+set(misc_tools_SOURCES
   testing/misc_tools.c
   testing/misc_tools.h)
+if(EXECUTION_TRACE)
+  set(misc_tools_SOURCES ${misc_tools_SOURCES}
+    testing/trace.cc)
+endif()
+add_library(misc_tools ${misc_tools_SOURCES})
 target_link_modules(misc_tools toxcore)
 
 set(TEST_TIMEOUT_SECONDS "" CACHE STRING "Limit runtime of each test to the number of seconds specified")
diff --git a/testing/BUILD.bazel b/testing/BUILD.bazel
index 34f2d44c..5a2a0194 100644
--- a/testing/BUILD.bazel
+++ b/testing/BUILD.bazel
@@ -1,5 +1,4 @@
-load("@rules_cc//cc:defs.bzl", "cc_binary")
-load("//tools:no_undefined.bzl", "cc_library")
+load("@rules_cc//cc:defs.bzl", "cc_binary", "cc_library")
 
 cc_library(
     name = "misc_tools",
@@ -9,6 +8,13 @@ cc_library(
     deps = ["//c-toxcore/toxcore"],
 )
 
+cc_library(
+    name = "trace",
+    srcs = ["trace.cc"],
+    visibility = ["//c-toxcore:__subpackages__"],
+    alwayslink = True,
+)
+
 cc_binary(
     name = "DHT_test",
     srcs = ["DHT_test.c"],
diff --git a/testing/trace.cc b/testing/trace.cc
new file mode 100644
index 00000000..ecd31726
--- /dev/null
+++ b/testing/trace.cc
@@ -0,0 +1,198 @@
+/* SPDX-License-Identifier: GPL-3.0-or-later
+ * Copyright © 2020 The TokTok team.
+ */
+#include <sys/param.h>
+#include <unistd.h>
+
+#include <algorithm>
+#include <array>
+#include <cassert>
+#include <cstdio>
+#include <cstring>
+#include <map>
+#include <memory>
+#include <string>
+
+#define LOG_TO_STDOUT 0
+
+/**
+ * This file contains the support code for using -finstrument-functions.
+ *
+ * If you link this into a program, e.g. a test program, that was compiled with
+ * -finstrument-functions, it will print an indented execution trace. E.g.:
+ *
+ * @code
+ * int g() { return 0; }
+ * int f() { return g(); }
+ * int main() { return f(); }
+ * @endcode
+ *
+ * Compiling the above with instrumentation and linking it with this file will
+ * result in the following output:
+ *
+ * @verbatim
+ * -> main
+ *  -> f
+ *   -> g
+ *   <- g
+ *  <- f
+ * <- main
+ * @endverbatim
+ *
+ * There are a few filter options you can apply below. Note that you'll need
+ * addr2line in your PATH for this to work.
+ */
+namespace {
+
+class CString {
+  char const *str_;
+
+ public:
+  // cppcheck-suppress noExplicitConstructor
+  constexpr CString(char const *str) : str_(str) {}
+
+  friend bool operator<(CString lhs, CString rhs) { return strcmp(lhs.str_, rhs.str_) < 0; }
+};
+
+template <std::size_t N>
+bool contains(CString const (&array)[N], std::string const &str) {
+  return std::binary_search(array, array + N, str.c_str());
+}
+
+struct Symbol {
+  std::string const name;
+  std::string const file;
+};
+
+/**
+ * This array lists functions that should *not* appear in the trace.
+ */
+constexpr CString exclusions[] = {
+    "__bswap_32", "logger_callback_log", "make_family", "make_proto", "make_socktype",
+};
+
+/**
+ * This array lists source files that *should* appear in the trace.
+ *
+ * If this array is empty, all files are traced.
+ */
+constexpr CString filter_sources[] = {
+    "onion.c",
+    "onion_announce.c",
+    "onion_client.c",
+};
+
+class ExecutionTrace {
+  using Process = std::unique_ptr<FILE, decltype(&pclose)>;
+  using File = std::unique_ptr<FILE, decltype(&fclose)>;
+
+  std::string const exe = []() {
+    std::array<char, PATH_MAX> result;
+    ssize_t const count = readlink("/proc/self/exe", result.data(), result.size());
+    assert(count > 0);
+    return count > 0 ? std::string(result.data(), count) : "/proc/self/exe";
+  }();
+
+#if LOG_TO_STDOUT
+  File const log_file{stdout, std::fclose};
+#else
+  File const log_file{std::fopen("trace.log", "w"), std::fclose};
+#endif
+  unsigned nesting = 0;
+  std::map<void *, Symbol> symbols;
+
+  static std::string sh(std::string cmd) {
+    std::string result;
+    Process pipe(popen(cmd.c_str(), "r"), pclose);
+    if (!pipe) {
+      return "<popen-failed>";
+    }
+    std::array<char, 128> buffer;
+    while (std::fgets(buffer.data(), buffer.size(), pipe.get()) != nullptr) {
+      result += buffer.data();
+    }
+    return result;
+  }
+
+  Symbol const &resolve(void *fn) {
+    // Already in the cache.
+    auto const found = symbols.find(fn);
+    if (found != symbols.end()) {
+      return found->second;
+    }
+
+    // 0x<64 bit number>\0
+    std::array<char, 16 + 3> addr;
+    std::snprintf(addr.data(), addr.size(), "0x%lx",
+                  static_cast<unsigned long>(reinterpret_cast<uintptr_t>(fn)));
+
+    std::string const output = sh("addr2line -fs -e " + exe + " " + addr.data());
+
+    std::size_t const newline = output.find_first_of('\n');
+    std::size_t const colon = output.find_first_of(':');
+
+    std::string const sym = output.substr(0, newline);
+    std::string const file = output.substr(newline + 1, colon - (newline + 1));
+
+    auto const inserted = symbols.insert({fn, {sym, file}});
+    return inserted.first->second;
+  }
+
+  void indent() const {
+    for (unsigned i = 0; i < nesting; i++) {
+      std::fputc(' ', log_file.get());
+    }
+  }
+
+  void print(char const *prefix, Symbol const &sym) {
+    indent();
+    std::fprintf(log_file.get(), "%s %s (%s)\n", prefix, sym.name.c_str(), sym.file.c_str());
+  }
+
+  static bool excluded(Symbol const &sym) {
+    if (sizeof(filter_sources) != 0) {
+      if (!contains(filter_sources, sym.file)) {
+        return true;
+      }
+    }
+    return contains(exclusions, sym.name);
+  }
+
+ public:
+  void enter(void *fn) {
+    Symbol const &sym = resolve(fn);
+    if (!excluded(sym)) {
+      print("->", sym);
+      ++nesting;
+    }
+  }
+
+  void exit(void *fn) {
+    Symbol const &sym = resolve(fn);
+    if (!excluded(sym)) {
+      --nesting;
+      print("<-", sym);
+    }
+  }
+};
+
+// We leak this one.
+static ExecutionTrace *trace;
+
+}  // namespace
+
+extern "C" void __cyg_profile_func_enter(void *this_fn, void *call_site)
+    __attribute__((__no_instrument_function__));
+void __cyg_profile_func_enter(void *this_fn, void *call_site) {
+  if (trace == nullptr) {
+    trace = new ExecutionTrace();
+  }
+  trace->enter(this_fn);
+}
+
+extern "C" void __cyg_profile_func_exit(void *this_fn, void *call_site)
+    __attribute__((__no_instrument_function__));
+void __cyg_profile_func_exit(void *this_fn, void *call_site) {
+  assert(trace != nullptr);
+  trace->exit(this_fn);
+}