Swift: address logging review comments

swift/README.md

@@ -4,6 +4,8 @@
 
 The Swift CodeQL package is an experimental and unsupported work in progress.
 
+##
+
 ## Building the Swift extractor
 
 First ensure you have Bazel installed, for example with
@@ -28,7 +30,9 @@ set up the search path
 in [the per-user CodeQL configuration file](https://docs.github.com/en/code-security/codeql-cli/using-the-codeql-cli/specifying-command-options-in-a-codeql-configuration-file#using-a-codeql-configuration-file)
 .
 
-## Code generation
+## Development
+
+### Code generation
 
 Run
 
@@ -41,7 +45,26 @@ to update generated files. This can be shortened to
 
 You can also run `../misc/codegen/codegen.py`, as long as you are beneath the `swift` directory.
 
-## IDE setup
+### Logging configuration
+
+A log file is produced for each run under `CODEQL_EXTRACTOR_SWIFT_LOG_DIR` (the usual DB log directory).
+
+You can use the 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`, and `level` is one of `trace`, `debug`, `info`,
+`warning`, `error`, `critical` or `no_logs` to turn logs completely off.
+Current output default levels are no binary logs, `info` logs or higher in the text file and `warning` logs or higher on
+standard error. By default, all loggers are configured with the lowest output level. Logger names are visible in the
+textual logs between `[...]`. Examples are `extractor/dispatcher` or `extractor/<source filename>.trap`. An example
+of `CODEQL_EXTRACTOR_SWIFT_LOG_LEVELS` usage is the following:
+
+```bash
+export CODEQL_EXTRACTOR_SWIFT_LOG_LEVELS=out:console:trace,out:text:no_logs,*:warning,*.trap:trace
+```
+
+This will turn off generation of a text log file, redirecting all logs to standard error, but will make all loggers only
+write warnings or above, except for trap emission logs which will output all logs.
 
 ### CLion and the native bazel plugin
 
@@ -84,3 +107,6 @@ In particular for breakpoints to work you might need to setup the following remo
 |-------------|--------------------------------------|
 | `swift`     | `/absolute/path/to/codeql/swift`     |
 | `bazel-out` | `/absolute/path/to/codeql/bazel-out` |
+
+### Thread safety
+The extractor is single-threaded, and there was no effort to make anything in it thread-safe.

swift/extractor/infra/log/SwiftLogging.cpp

@@ -96,55 +96,61 @@ void collectSeverityRules(const char* var, LevelConfiguration&& configuration) {
 
 }  // namespace
 
-void Log::configure(std::string_view root) {
-  auto& i = instance();
-
-  i.rootName = root;
+void Log::configureImpl(std::string_view root) {
+  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) {
+                       {sourceRules, binary.level, text.level, console.level, problems});
+  if (text || 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) {
+      if (text) {
         logFile.replace_extension(".log");
-        i.textFile.open(logFile);
-        if (!i.textFile) {
+        textFile.open(logFile);
+        if (!textFile) {
           problems.emplace_back("Unable to open text log file " + logFile.string());
-          i.text.level = Level::no_logs;
+          text.level = Level::no_logs;
         }
       }
-      if (i.binary) {
+      if (binary) {
         logFile.replace_extension(".blog");
-        i.binary.output.open(logFile, std::fstream::out | std::fstream::binary);
-        if (!i.binary.output) {
+        binary.output.open(logFile, std::fstream::out | std::fstream::binary);
+        if (!binary.output) {
           problems.emplace_back("Unable to open binary log file " + logFile.string());
-          i.binary.level = Level::no_logs;
+          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;
+      binary.level = Level::no_logs;
+      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();
+  LOG_INFO("Logging configured (binary: {}, text: {}, console: {})", binary.level, text.level,
+           console.level);
+  flushImpl();
 }
 
-void Log::flush() {
-  auto& i = instance();
-  i.session.consume(i);
+void Log::flushImpl() {
+  session.consume(*this);
+}
+
+Log::LoggerConfiguration Log::getLoggerConfigurationImpl(std::string_view name) {
+  LoggerConfiguration ret{session, rootName};
+  ret.fullyQualifiedName += '/';
+  ret.fullyQualifiedName += name;
+  ret.level = std::min({binary.level, text.level, console.level});
+  ret.level = getLevelFor(ret.fullyQualifiedName, sourceRules, ret.level);
+  return ret;
 }
 
 Log& Log::write(const char* buffer, std::streamsize size) {
@@ -154,28 +160,9 @@ Log& Log::write(const char* buffer, std::streamsize 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

@@ -10,11 +10,13 @@
 #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();`
+// defined in the current scope. Domain-specific loggers can be added or used by either:
+// * providing a class field called `logger` (as `Logger::operator()()` returns itself)
+// * declaring a local `logger` variable (to be used for one-time execution like code in `main`)
+// * declaring a `Logger& logger()` function returning a reference to a static local variable
+// * passing a logger around using a `Logger& logger` function parameter
+// They are created with a name that appears in the logs and can be used to filter debug levels (see
+// `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__)
@@ -68,7 +70,52 @@ class Log {
  public:
   using Level = binlog::Severity;
 
+  // Internal data required to build `Logger` instances
+  struct LoggerConfiguration {
+    binlog::Session& session;
+    std::string fullyQualifiedName;
+    Level level;
+  };
+
+  // Configure logging. This consists in
+  // * 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 below. By default, all
+  //   loggers are configured with the lowest output level
+  static void configure(std::string_view root) { instance().configureImpl(root); }
+
+  // Flush logs to the designated outputs
+  static void flush() { instance().flushImpl(); }
+
+  // create `Logger` configuration, used internally by `Logger`'s constructor
+  static LoggerConfiguration getLoggerConfiguration(std::string_view name) {
+    return instance().getLoggerConfigurationImpl(name);
+  }
+
  private:
+  static constexpr const char* format = "%u %S [%n] %m (%G:%L)\n";
+
+  Log() = default;
+
+  static Log& instance() {
+    static Log ret;
+    return ret;
+  }
+
+  static class Logger& logger();
+
+  void configureImpl(std::string_view root);
+  void flushImpl();
+  LoggerConfiguration getLoggerConfigurationImpl(std::string_view name);
+
+  // make `session.consume(*this)` work, which requires access to `write`
+  friend binlog::Session;
+  Log& write(const char* buffer, std::streamsize size);
+
   // Output filtered according to a configured log level
   template <typename Output>
   struct FilteredOutput {
@@ -93,8 +140,6 @@ class Log {
   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};
@@ -102,53 +147,14 @@ class Log {
   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); }
+  explicit Logger(const std::string& name) : Logger(Log::getLoggerConfiguration(name)) {}
 
   binlog::SessionWriter& writer() { return w; }
   Log::Level level() const { return level_; }
@@ -156,9 +162,17 @@ class Logger {
   // 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; }
+
+ private:
+  static constexpr size_t queueSize = 1 << 20;  // default taken from binlog
+
+  explicit Logger(Log::LoggerConfiguration&& configuration)
+      : w{configuration.session, queueSize, /* id */ 0,
+          std::move(configuration.fullyQualifiedName)},
+        level_{configuration.level} {}
+
+  binlog::SessionWriter w;
+  Log::Level level_;
 };
 
-// default logger
-Logger& logger();
-
 }  // namespace codeql

swift/extractor/main.cpp

@@ -215,9 +215,11 @@ int main(int argc, char** argv, char** envp) {
 
   const auto configuration = configure(argc, argv);
   codeql::Log::configure("extractor");
-  auto& logger = codeql::logger();
-  LOG_INFO("calling extractor with arguments \"{}\"", argDump(argc, argv));
-  LOG_DEBUG("environment:\n{}\n", envDump(envp));
+  {
+    codeql::Logger logger{"main"};
+    LOG_INFO("calling extractor with arguments \"{}\"", argDump(argc, argv));
+    LOG_DEBUG("environment:\n{}\n", envDump(envp));
+  }
 
   auto openInterception = codeql::setupFileInterception(configuration);
 

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

@@ -1,31 +0,0 @@
-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

@@ -64,5 +64,4 @@ def load_dependencies(workspace_name):
         repository = "morganstanley/binlog",
         commit = "3fef8846f5ef98e64211e7982c2ead67e0b185a6",
         sha256 = "f5c61d90a6eff341bf91771f2f465be391fd85397023e1b391c17214f9cbd045",
-        patches = ["01-change-severity-printing"],
     )