Swift: add logging infrastructure

swift/extractor/infra/BUILD.bazel

@@ -8,6 +8,7 @@ swift_cc_library(
     deps = [
         "//swift/extractor/config",
         "//swift/extractor/infra/file",
+        "//swift/extractor/infra/log",
         "//swift/extractor/trap",
         "//swift/third_party/swift-llvm-support",
     ],

swift/extractor/infra/log/BUILD.bazel

@@ -0,0 +1,7 @@
+cc_library(
+    name = "log",
+    srcs = glob(["*.cpp"]),
+    hdrs = glob(["*.h"]),
+    visibility = ["//visibility:public"],
+    deps = ["@binlog"],
+)

swift/extractor/infra/log/SwiftLogging.cpp

@@ -0,0 +1,181 @@
+#include "swift/extractor/infra/log/SwiftLogging.h"
+
+#include <filesystem>
+#include <stdlib.h>
+#include <optional>
+
+#define LEVEL_REGEX_PATTERN "trace|debug|info|warning|error|critical|no_logs"
+
+BINLOG_ADAPT_ENUM(codeql::Log::Level, trace, debug, info, warning, error, critical, no_logs)
+
+namespace codeql {
+
+namespace {
+using LevelRule = std::pair<std::regex, Log::Level>;
+using LevelRules = std::vector<LevelRule>;
+
+Log::Level getLevelFor(std::string_view name, const LevelRules& rules, Log::Level dflt) {
+  for (auto it = rules.rbegin(); it != rules.rend(); ++it) {
+    if (std::regex_match(std::begin(name), std::end(name), it->first)) {
+      return it->second;
+    }
+  }
+  return dflt;
+}
+
+const char* getEnvOr(const char* var, const char* deflt) {
+  if (const char* ret = getenv(var)) {
+    return ret;
+  }
+  return deflt;
+}
+
+std::string_view matchToView(std::csub_match m) {
+  return {m.first, static_cast<size_t>(m.length())};
+}
+
+Log::Level stringToLevel(std::string_view v) {
+  if (v == "trace") return Log::Level::trace;
+  if (v == "debug") return Log::Level::debug;
+  if (v == "info") return Log::Level::info;
+  if (v == "warning") return Log::Level::warning;
+  if (v == "error") return Log::Level::error;
+  if (v == "critical") return Log::Level::critical;
+  return Log::Level::no_logs;
+}
+
+Log::Level matchToLevel(std::csub_match m) {
+  return stringToLevel(matchToView(m));
+}
+
+struct LevelConfiguration {
+  LevelRules& sourceRules;
+  Log::Level& binSeverity;
+  Log::Level& textSeverity;
+  Log::Level& consoleSeverity;
+  std::vector<std::string>& problems;
+};
+
+void collectSeverityRules(const char* var, LevelConfiguration&& configuration) {
+  if (auto levels = getEnvOr(var, nullptr)) {
+    // expect comma-separated <glob pattern>:<log severity>
+    std::regex comma{","};
+    std::regex levelAssignment{R"((?:([*./\w]+)|(?:out:(bin|text|console))):()" LEVEL_REGEX_PATTERN
+                               ")"};
+    std::cregex_token_iterator begin{levels, levels + strlen(levels), comma, -1};
+    std::cregex_token_iterator end{};
+    for (auto it = begin; it != end; ++it) {
+      std::cmatch match;
+      if (std::regex_match(it->first, it->second, match, levelAssignment)) {
+        auto level = matchToLevel(match[3]);
+        if (match[1].matched) {
+          auto pattern = match[1].str();
+          // replace all "*" with ".*" and all "." with "\.", turning the glob pattern into a regex
+          std::string::size_type pos = 0;
+          while ((pos = pattern.find_first_of("*.", pos)) != std::string::npos) {
+            pattern.insert(pos, (pattern[pos] == '*') ? "." : "\\");
+            pos += 2;
+          }
+          configuration.sourceRules.emplace_back(pattern, level);
+        } else {
+          auto out = matchToView(match[2]);
+          if (out == "bin") {
+            configuration.binSeverity = level;
+          } else if (out == "text") {
+            configuration.textSeverity = level;
+          } else if (out == "console") {
+            configuration.consoleSeverity = level;
+          }
+        }
+      } else {
+        configuration.problems.emplace_back("Malformed log level rule: " + it->str());
+      }
+    }
+  }
+}
+
+}  // namespace
+
+void Log::configure(std::string_view root) {
+  auto& i = instance();
+
+  i.rootName = root;
+  // as we are configuring logging right now, we collect problems and log them at the end
+  std::vector<std::string> problems;
+  collectSeverityRules("CODEQL_EXTRACTOR_SWIFT_LOG_LEVELS",
+                       {i.sourceRules, i.binary.level, i.text.level, i.console.level, problems});
+  if (i.text || i.binary) {
+    std::filesystem::path logFile = getEnvOr("CODEQL_EXTRACTOR_SWIFT_LOG_DIR", ".");
+    logFile /= root;
+    logFile /= std::to_string(std::chrono::system_clock::now().time_since_epoch().count());
+    std::error_code ec;
+    std::filesystem::create_directories(logFile.parent_path(), ec);
+    if (!ec) {
+      if (i.text) {
+        logFile.replace_extension(".log");
+        i.textFile.open(logFile);
+        if (!i.textFile) {
+          problems.emplace_back("Unable to open text log file " + logFile.string());
+          i.text.level = Level::no_logs;
+        }
+      }
+      if (i.binary) {
+        logFile.replace_extension(".blog");
+        i.binary.output.open(logFile, std::fstream::out | std::fstream::binary);
+        if (!i.binary.output) {
+          problems.emplace_back("Unable to open binary log file " + logFile.string());
+          i.binary.level = Level::no_logs;
+        }
+      }
+    } else {
+      problems.emplace_back("Unable to create log directory " + logFile.parent_path().string() +
+                            ": " + ec.message());
+      i.binary.level = Level::no_logs;
+      i.text.level = Level::no_logs;
+    }
+  }
+  for (const auto& problem : problems) {
+    LOG_ERROR("{}", problem);
+  }
+  LOG_INFO("Logging configured (binary: {}, text: {}, console: {})", i.binary.level, i.text.level,
+           i.console.level);
+  flush();
+}
+
+void Log::flush() {
+  auto& i = instance();
+  i.session.consume(i);
+}
+
+Log& Log::write(const char* buffer, std::streamsize size) {
+  if (text) text.write(buffer, size);
+  if (binary) binary.write(buffer, size);
+  if (console) console.write(buffer, size);
+  return *this;
+}
+
+Log::Level Log::getLevelForSource(std::string_view name) const {
+  auto dflt = std::min({binary.level, text.level, console.level});
+  auto level = getLevelFor(name, sourceRules, dflt);
+  // avoid Log::logger() constructor loop
+  if (name.size() > rootName.size() && name.substr(rootName.size() + 1) != "logging") {
+    LOG_DEBUG("setting up logger \"{}\" with level {}", name, level);
+  }
+  return level;
+}
+
+Logger& Log::logger() {
+  static Logger ret{"logging"};
+  return ret;
+}
+
+void Logger::setName(std::string name) {
+  level_ = Log::instance().getLevelForSource(name);
+  w.setName(std::move(name));
+}
+
+Logger& logger() {
+  static Logger ret{};
+  return ret;
+}
+}  // namespace codeql

swift/extractor/infra/log/SwiftLogging.h

@@ -0,0 +1,164 @@
+#pragma once
+
+#include <fstream>
+#include <iostream>
+#include <regex>
+#include <vector>
+
+#include <binlog/binlog.hpp>
+#include <binlog/TextOutputStream.hpp>
+#include <binlog/EventFilter.hpp>
+
+// Logging macros. These will call `logger()` to get a Logger instance, picking up any `logger`
+// defined in the current scope. A default `codeql::logger()` is provided, otherwise domain-specific
+// loggers can be added as class fields called `logger` (as `Logger::operator()()` returns itself).
+// Domain specific loggers are set up with a name that appears in the log and can be used to filter
+// debug levels (see `Logger`). If working in the global namespace, the default logger can be used
+// by defining `auto& logger = codeql::logger();`
+#define LOG_CRITICAL(...) LOG_IMPL(codeql::Log::Level::critical, __VA_ARGS__)
+#define LOG_ERROR(...) LOG_IMPL(codeql::Log::Level::error, __VA_ARGS__)
+#define LOG_WARNING(...) LOG_IMPL(codeql::Log::Level::warning, __VA_ARGS__)
+#define LOG_INFO(...) LOG_IMPL(codeql::Log::Level::info, __VA_ARGS__)
+#define LOG_DEBUG(...) LOG_IMPL(codeql::Log::Level::debug, __VA_ARGS__)
+#define LOG_TRACE(...) LOG_IMPL(codeql::Log::Level::trace, __VA_ARGS__)
+
+// avoid calling into binlog's original macros
+#undef BINLOG_CRITICAL
+#undef BINLOG_CRITICAL_W
+#undef BINLOG_CRITICAL_C
+#undef BINLOG_CRITICAL_WC
+#undef BINLOG_ERROR
+#undef BINLOG_ERROR_W
+#undef BINLOG_ERROR_C
+#undef BINLOG_ERROR_WC
+#undef BINLOG_WARNING
+#undef BINLOG_WARNING_W
+#undef BINLOG_WARNING_C
+#undef BINLOG_WARNING_WC
+#undef BINLOG_INFO
+#undef BINLOG_INFO_W
+#undef BINLOG_INFO_C
+#undef BINLOG_INFO_WC
+#undef BINLOG_DEBUG
+#undef BINLOG_DEBUG_W
+#undef BINLOG_DEBUG_C
+#undef BINLOG_DEBUG_WC
+#undef BINLOG_TRACE
+#undef BINLOG_TRACE_W
+#undef BINLOG_TRACE_C
+#undef BINLOG_TRACE_WC
+
+// only do the actual logging if the picked up `Logger` instance is configured to handle the
+// provided log level
+#define LOG_IMPL(severity, ...)                                                        \
+  do {                                                                                 \
+    if (auto& _logger = logger(); severity >= _logger.level()) {                       \
+      BINLOG_CREATE_SOURCE_AND_EVENT(_logger.writer(), severity, , binlog::clockNow(), \
+                                     __VA_ARGS__);                                     \
+    }                                                                                  \
+  } while (false)
+
+namespace codeql {
+
+// This class is responsible for the global log state (outputs, log level rules, flushing)
+// State is stored in the singleton `Log::instance()`.
+// Before using logging, `Log::configure("<name>")` should be used (e.g.
+// `Log::configure("extractor")`). Then, `Log::flush()` should be regularly called.
+class Log {
+ public:
+  using Level = binlog::Severity;
+
+ private:
+  // Output filtered according to a configured log level
+  template <typename Output>
+  struct FilteredOutput {
+    binlog::Severity level;
+    Output output;
+    binlog::EventFilter filter{
+        [this](const binlog::EventSource& src) { return src.severity >= level; }};
+
+    template <typename... Args>
+    FilteredOutput(Level level, Args&&... args)
+        : level{level}, output{std::forward<Args>(args)...} {}
+
+    FilteredOutput& write(const char* buffer, std::streamsize size) {
+      filter.writeAllowed(buffer, size, output);
+      return *this;
+    }
+
+    // if configured as `no_logs`, the output is effectively disabled
+    explicit operator bool() const { return level < Level::no_logs; }
+  };
+
+  using LevelRule = std::pair<std::regex, Level>;
+  using LevelRules = std::vector<LevelRule>;
+
+  static constexpr const char* format = "%u %S [%n] %m (%G:%L)\n";
+
+  binlog::Session session;
+  std::ofstream textFile;
+  FilteredOutput<std::ofstream> binary{Level::no_logs};
+  FilteredOutput<binlog::TextOutputStream> text{Level::info, textFile, format};
+  FilteredOutput<binlog::TextOutputStream> console{Level::warning, std::cerr, format};
+  LevelRules sourceRules;
+  std::string rootName;
+
+  Log() = default;
+
+  static Log& instance() {
+    static Log ret;
+    return ret;
+  }
+
+  friend class Logger;
+  friend binlog::Session;
+
+  Level getLevelForSource(std::string_view name) const;
+  Log& write(const char* buffer, std::streamsize size);
+  static class Logger& logger();
+
+ public:
+  // Configure logging. This consists in
+  // * setting up a default logger with `root` as name
+  // * using environment variable `CODEQL_EXTRACTOR_SWIFT_LOG_DIR` to choose where to dump the log
+  //   file(s). Log files will go to a subdirectory thereof named after `root`
+  // * using environment variable `CODEQL_EXTRACTOR_SWIFT_LOG_LEVELS` to configure levels for
+  //   loggers and outputs. This must have the form of a comma separated `spec:level` list, where
+  //   `spec` is either a glob pattern (made up of alphanumeric, `/`, `*` and `.` characters) for
+  //   matching logger names or one of `out:bin`, `out:text` or `out:console`.
+  //   Output default levels can be seen in the corresponding initializers above. By default, all
+  //   loggers are configured with the lowest output level
+  static void configure(std::string_view root);
+
+  // Flush logs to the designated outputs
+  static void flush();
+};
+
+// This class represent a named domain-specific logger, responsible for pushing logs using the
+// underlying `binlog::SessionWriter` class. This has a configured log level, so that logs on this
+// `Logger` with a level lower than the configured one are no-ops.
+class Logger {
+  binlog::SessionWriter w{Log::instance().session};
+  Log::Level level_{Log::Level::no_logs};
+
+  void setName(std::string name);
+
+  friend Logger& logger();
+  // constructor for the default `Logger`
+  explicit Logger() { setName(Log::instance().rootName); }
+
+ public:
+  explicit Logger(const std::string& name) { setName(Log::instance().rootName + '/' + name); }
+
+  binlog::SessionWriter& writer() { return w; }
+  Log::Level level() const { return level_; }
+
+  // make defining a `Logger logger` field be equivalent to providing a `Logger& logger()` function
+  // in order to be picked up by logging macros
+  Logger& operator()() { return *this; }
+};
+
+// default logger
+Logger& logger();
+
+}  // namespace codeql

swift/third_party/binlog/BUILD.binlog.bazel

@@ -0,0 +1,19 @@
+cc_library(
+  name = "binlog",
+  hdrs = glob(["include/**/*.hpp"]),
+  srcs = glob(["include/**/*.cpp"]),
+  includes = ["include"],
+  visibility = ["//visibility:public"],
+)
+
+cc_binary(
+  name = "bread",
+  srcs = ["bin/bread.cpp", "bin/printers.hpp", "bin/printers.cpp", "bin/getopt.hpp"],
+  deps = [":binlog"],
+)
+
+cc_binary(
+  name = "brecovery",
+  srcs = ["bin/brecovery.cpp", "bin/getopt.hpp"],
+  deps = [":binlog"],
+)

swift/third_party/binlog/patches/01-change-severity-printing.patch

@@ -0,0 +1,31 @@
+diff --git a/include/binlog/Severity.hpp b/include/binlog/Severity.hpp
+index b1c9a60..6deec29 100644
+--- a/include/binlog/Severity.hpp
++++ b/include/binlog/Severity.hpp
+@@ -18,18 +18,18 @@ enum class Severity : std::uint16_t
+   no_logs  = 1 << 15, // For filtering, not to create events
+ };
+
+-inline mserialize::cx_string<4> severityToString(Severity severity)
++inline mserialize::cx_string<3> severityToString(Severity severity)
+ {
+   switch (severity)
+   {
+-    case Severity::trace:    return mserialize::cx_string<4>{"TRAC"};
+-    case Severity::debug:    return mserialize::cx_string<4>{"DEBG"};
+-    case Severity::info:     return mserialize::cx_string<4>{"INFO"};
+-    case Severity::warning:  return mserialize::cx_string<4>{"WARN"};
+-    case Severity::error:    return mserialize::cx_string<4>{"ERRO"};
+-    case Severity::critical: return mserialize::cx_string<4>{"CRIT"};
+-    case Severity::no_logs:  return mserialize::cx_string<4>{"NOLG"};
+-    default:                 return mserialize::cx_string<4>{"UNKW"};
++    case Severity::trace:    return mserialize::cx_string<3>{"TRC"};
++    case Severity::debug:    return mserialize::cx_string<3>{"DBG"};
++    case Severity::info:     return mserialize::cx_string<3>{"INF"};
++    case Severity::warning:  return mserialize::cx_string<3>{"WRN"};
++    case Severity::error:    return mserialize::cx_string<3>{"ERR"};
++    case Severity::critical: return mserialize::cx_string<3>{"CRT"};
++    case Severity::no_logs:  return mserialize::cx_string<3>{"NOL"};
++    default:                 return mserialize::cx_string<3>{"UNK"};
+   }
+ }

swift/third_party/load.bzl

@@ -12,16 +12,29 @@ _swift_arch_map = {
     "macOS-X64": "darwin_x86_64",
 }
 
-def _get_label(repository_name, package, target):
-    return "@%s//swift/third_party/%s:%s" % (repository_name, package, target)
+def _get_label(workspace_name, package, target):
+    return "@%s//swift/third_party/%s:%s" % (workspace_name, package, target)
 
-def _get_build(repository_name, package):
-    return _get_label(repository_name, package, "BUILD.%s.bazel" % package)
+def _get_build(workspace_name, package):
+    return _get_label(workspace_name, package, "BUILD.%s.bazel" % package)
 
-def _get_patch(repository_name, package, patch):
-    return _get_label(repository_name, package, "patches/%s.patch" % patch)
+def _get_patch(workspace_name, package, patch):
+    return _get_label(workspace_name, package, "patches/%s.patch" % patch)
 
-def load_dependencies(repository_name):
+def _github_archive(*, name, workspace_name, repository, commit, sha256 = None, patches = None):
+    github_name = repository[repository.index("/") + 1:]
+    patches = [_get_patch(workspace_name, name, p) for p in patches or []]
+    http_archive(
+        name = name,
+        url = "https://github.com/%s/archive/%s.zip" % (repository, commit),
+        strip_prefix = "%s-%s" % (github_name, commit),
+        build_file = _get_build(workspace_name, name),
+        sha256 = sha256,
+        patch_args = ["-p1"],
+        patches = patches,
+    )
+
+def load_dependencies(workspace_name):
     for repo_arch, arch in _swift_arch_map.items():
         sha256 = _swift_sha_map[repo_arch]
 
@@ -31,16 +44,25 @@ def load_dependencies(repository_name):
                 _swift_prebuilt_version,
                 repo_arch,
             ),
-            build_file = _get_build(repository_name, "swift-llvm-support"),
+            build_file = _get_build(workspace_name, "swift-llvm-support"),
             sha256 = sha256,
             patch_args = ["-p1"],
             patches = [],
         )
 
-    http_archive(
+    _github_archive(
         name = "picosha2",
-        url = "https://github.com/okdshin/PicoSHA2/archive/27fcf6979298949e8a462e16d09a0351c18fcaf2.zip",
-        strip_prefix = "PicoSHA2-27fcf6979298949e8a462e16d09a0351c18fcaf2",
-        build_file = _get_build(repository_name, "picosha2"),
+        workspace_name = workspace_name,
+        repository = "okdshin/PicoSHA2",
+        commit = "27fcf6979298949e8a462e16d09a0351c18fcaf2",
         sha256 = "d6647ca45a8b7bdaf027ecb68d041b22a899a0218b7206dee755c558a2725abb",
     )
+
+    _github_archive(
+        name = "binlog",
+        workspace_name = workspace_name,
+        repository = "morganstanley/binlog",
+        commit = "3fef8846f5ef98e64211e7982c2ead67e0b185a6",
+        sha256 = "f5c61d90a6eff341bf91771f2f465be391fd85397023e1b391c17214f9cbd045",
+        patches = ["01-change-severity-printing"],
+    )