Swift: introduce usage of binlog #12745

redsun82 · 2023-04-03T12:30:31Z

This introduces a logging module in the Swift extractor, with some first examples.

This is built on top of binlog, though it introduces more configurability: while binlog allows to set a global minimal severity of logs, this patch allows to set minimal log levels for:

the different outputs (currently three: binary log file, textual log file and standard error)
the different sources (Logger instances), e.g. extractor/dispatcher or extractor/logging

The logging macros will pick up the Logger instance to use by calling logger(), so the writer for a specific area of the code can be put in place by either:

providing a Logger& logger() function within the scope
providing a Logger logger class member (instance or static), as Logger::operator()() returns *this
having a local variable, reference or parameter of type Logger called logger

I've been hesitant to have this implicit reference to a default logger name as opposed to explicitly passing a logger reference to the logging macros, but for the moment decided for this, as in my experience passing an explicit logger instance always ends up being a repetitive log or logger additional argument everywhere in the code, not particularly adding anything to readability. But comments are welcome 🙂

Some first actual logging has been introduced at the startup of the extractor, in the dispatcher printing names of encountered declarations. The more significant addition is logging of all emitted entities, leveraging codegen to create the proper binlog adapters. This creates logs like

2023-03-31 10:19:49.287373955 TRAC [extractor/non_empty.swift.trap] codeql::CallExpr{ id: #9, type: #a, function: #b, arguments: [#14, #21, #26] } (TrapDomain.h:22)

Logging levels are configurable per output and per Logger instance via the CODEQL_EXTRACTOR_SWIFT_LOG_LEVELS environment variable. As a complex example:

export CODEQL_EXTRACTOR_SWIFT_LOG_LEVELS=out:console:trace,out:text:no_logs,*:warning,*.trap:trace

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.

For the moment as a default:

the binary log file is disabled
the textual log file prints info or higher
warning or higher get printed to standard error

Once this is a bit more mature we should experiment with the binary file format on real world projects, to see if we can get any benefit from it. For the moment I propose to stick with textual format to minimize initial friction. The binary format can be read either with a globally installed bread binary or with bazel run @binlog//:bread -- /absolute/path/to/log.blog.

sashabu

Design looks good aside from a few comments. I'll do a more thorough review once those are addressed.

swift/extractor/infra/log/SwiftLogging.h

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

swift/extractor/infra/log/SwiftLogging.h

sashabu

Thanks for your patience!

sashabu · 2023-04-06T12:46:11Z

swift/README.md

+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


Would it be clearer if we called it min_level?

sashabu · 2023-04-06T12:48:00Z

swift/README.md

+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


"lowest output level" is ambiguous - is it the lowest level (i.e. trace and above) or the lowest output (i.e. no_logs)?

sashabu · 2023-04-06T12:59:04Z

swift/extractor/infra/SwiftDispatcher.h

@@ -151,7 +152,13 @@ class SwiftDispatcher {
      return *l;
    }
    waitingForNewLabel = e;
+    // TODO: more generic and informational visiting one-line log
+    if constexpr (std::is_convertible_v<E, const swift::ValueDecl*>) {
+      const swift::ValueDecl* x = e;


Why do we need a separate variable here?

ah, that was meant to be temporary to get the IDE to autocomplete stuff for me, I think I'll just drop this log and leave a TODO

sashabu · 2023-04-06T13:00:34Z

swift/extractor/infra/SwiftDispatcher.h

+    // TODO: more generic and informational visiting one-line log
+    if constexpr (std::is_convertible_v<E, const swift::ValueDecl*>) {
+      const swift::ValueDecl* x = e;
+      LOG_TRACE("{}", x->getName().getBaseIdentifier().str());


Would it make sense to add some context here? E.g. make the message "Visiting declaration: {}"?

definitely, though I think I will be moving this kind of tracing to the translators, where I also have programmatic access to the swift entity type names because of macro metaprogramming. But I'll leave it for a PR down the road, and for now remove this draft log

sashabu · 2023-04-06T13:05:56Z

swift/extractor/infra/log/SwiftLogging.cpp

+  return dflt;
+}
+
+const char* getEnvOr(const char* var, const char* deflt) {


Nit: We use deflt here and dflt in getLevelFor. Can we pick one for consistency?

sashabu · 2023-04-06T13:36:03Z

swift/extractor/infra/log/SwiftLogging.cpp

+  // 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",
+                       {sourceRules, binary.level, text.level, console.level, problems});


I'm struggling to follow the data flow through LevelConfiguration&& configuration. I think it'd be clearer if collectSeverityRules were a member function that took a var and returned the problems (and had the other arguments hard-coded).

sashabu · 2023-04-06T13:43:04Z

swift/extractor/infra/log/SwiftLogging.h

+namespace codeql {
+
+// tools should define this to tweak the root name of all loggers
+extern const char* const logRootName;


Nit: Make this a string_view?

sashabu · 2023-04-06T13:44:58Z

swift/extractor/main.cpp

+    ret += *env;
+    ret += '\n';
+  }
+  ret.pop_back();


Hmm... Maybe keep the newline to make it more obvious when the multi-line log message ends in a text log?

sashabu · 2023-04-06T13:47:54Z

swift/extractor/main.cpp

+static auto argDump(int argc, char** argv) {
+  std::string ret;
+  for (auto arg = argv + 1; arg < argv + argc; ++arg) {
+    ret += *arg;


(Not for this PR) Have we considered using Abseil or Boost string libraries? This looks like a job for absl::StrJoin or boost::algorithm::join, and I wouldn't be surprised if we have other places that could benefit similarly.

yeah, I think I wanted to bring in abseil at some point, would be worth it I think

sashabu · 2023-04-06T14:26:05Z

swift/extractor/trap/TrapLabel.h

+  size_t strSize() const {
+    if (id_ == undefined) return 17;  // #ffffffffffffffff
+    if (id_ == 0) return 2;           // #0
+    return /* # */ 1 + /* hex digits */ static_cast<size_t>(ceil(log2(id_ + 1) / 4));


Optional: The floating-point log looks painful. Are any of the following better options?

C++20 std::bit_width;

Abseil's backport absl::bit_width;

A while (id >>= 4) digits+=4;-type loop (which unfortunately compiles to a literal shift/add/cmp loop instead of using LZCNT);

Return a fixed-size, null-terminated buffer from str() (e.g. std::array<char, 18>) and use strlen(str().data()).

via the mserialize specialisations this is also used for every log. That's why I wanted to avoid option 4, to avoid each label being converted twice for each log (once to calculate its size, another to store it). Maybe I'll leave a todo to switch to bit_width, whichever comes first between abseil and C++20 🙂

I did say "optional", so a todo sounds good. That said, I wouldn't make any bets on a floating-point log being faster than an int->hex conversion!

redsun82 added 4 commits April 3, 2023 11:47

Swift: add logging infrastructure

ed48065

Swift: add logging to main

3fc4881

Swift: add preliminary logging to dispatcher

a386c58

Swift: add trace logging of all trap emission

abc0c7c

redsun82 requested a review from sashabu April 3, 2023 12:30

github-actions bot added the Swift label Apr 3, 2023

sashabu requested changes Apr 3, 2023

View reviewed changes

Swift: address logging review comments

6c932bc

github-actions bot added the documentation label Apr 4, 2023

Swift: expand Logger doc comment

5a01fec

redsun82 marked this pull request as ready for review April 5, 2023 04:14

redsun82 requested review from a team as code owners April 5, 2023 04:14

redsun82 requested a review from sashabu April 5, 2023 04:14

redsun82 added 3 commits April 5, 2023 06:30

Swift: rename LOG_IMPL->LOG_WITH_LEVEL and strengthen it

6ef9088

Swift: remove Log::configure

a5162b0

Swift: make trap domain logger names more informative

acaa6a5

sashabu requested changes Apr 6, 2023

View reviewed changes

Swift: introduce usage of binlog #12745

Swift: introduce usage of binlog #12745

redsun82 commented Apr 3, 2023 •

edited

sashabu left a comment

sashabu left a comment

sashabu Apr 6, 2023

sashabu Apr 6, 2023

sashabu Apr 6, 2023

redsun82 Apr 6, 2023

sashabu Apr 6, 2023

redsun82 Apr 6, 2023

sashabu Apr 6, 2023

sashabu Apr 6, 2023

sashabu Apr 6, 2023

sashabu Apr 6, 2023

sashabu Apr 6, 2023

redsun82 Apr 6, 2023

sashabu Apr 6, 2023

redsun82 Apr 6, 2023

sashabu Apr 6, 2023

Swift: introduce usage of binlog #12745

Are you sure you want to change the base?

Swift: introduce usage of binlog #12745

Conversation

redsun82 commented Apr 3, 2023 • edited

sashabu left a comment

Choose a reason for hiding this comment

sashabu left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

redsun82 commented Apr 3, 2023 •

edited