Merge pull request #12860 from github/redsun82/swift-logging-assertions-and-prints

Swift: replace assertions and direct prints with proper logging

Author: redsun82

misc/codegen/templates/cpp_classes_h.mustache

@@ -42,34 +42,12 @@ struct {{name}}{{#has_bases}} : {{#bases}}{{^first}}, {{/first}}{{ref.name}}{{/b
  {{/final}}
   template <typename F>
   void forEachLabel(F f) {
-    {{#final}}
-    f("id", -1, id);
-    {{/final}}
-    {{#bases}}
-    {{ref.name}}::forEachLabel(f);
-    {{/bases}}
-    {{#fields}}
-    {{#is_label}}
-    {{#is_repeated}}
-    for (auto i = 0u; i < {{field_name}}.size(); ++i) {
-      {{#is_optional}}
-      if ({{field_name}}[i]) f("{{field_name}}", i, *{{field_name}}[i]);
-      {{/is_optional}}
-      {{^is_optional}}
-      f("{{field_name}}", i, {{field_name}}[i]);
-      {{/is_optional}}
-    }
-    {{/is_repeated}}
-    {{^is_repeated}}
-    {{#is_optional}}
-    if ({{field_name}}) f("{{field_name}}", -1, *{{field_name}});
-    {{/is_optional}}
-    {{^is_optional}}
-    f("{{field_name}}", -1, {{field_name}});
-    {{/is_optional}}
-    {{/is_repeated}}
-    {{/is_label}}
-    {{/fields}}
+    {{>cpp_for_each_label_body}}
+  }
+
+  template <typename F>
+  void forEachLabel(F f) const {
+    {{>cpp_for_each_label_body}}
   }
 
  protected:

misc/codegen/templates/cpp_for_each_label_body.mustache

@@ -0,0 +1,28 @@
+{{#final}}
+f("id", -1, id);
+{{/final}}
+{{#bases}}
+{{ref.name}}::forEachLabel(f);
+{{/bases}}
+{{#fields}}
+{{#is_label}}
+{{#is_repeated}}
+for (auto i = 0u; i < {{field_name}}.size(); ++i) {
+  {{#is_optional}}
+  if ({{field_name}}[i]) f("{{field_name}}", i, *{{field_name}}[i]);
+  {{/is_optional}}
+  {{^is_optional}}
+  f("{{field_name}}", i, {{field_name}}[i]);
+  {{/is_optional}}
+}
+{{/is_repeated}}
+{{^is_repeated}}
+{{#is_optional}}
+if ({{field_name}}) f("{{field_name}}", -1, *{{field_name}});
+{{/is_optional}}
+{{^is_optional}}
+f("{{field_name}}", -1, {{field_name}});
+{{/is_optional}}
+{{/is_repeated}}
+{{/is_label}}
+{{/fields}}

misc/codegen/templates/trap_traps_h.mustache

@@ -23,11 +23,12 @@ struct {{name}}Trap {
 
   template <typename F>
   void forEachLabel(F f) {
-    {{#fields}}
-    {{#is_label}}
-    f("{{field_name}}", -1, {{field_name}});
-    {{/is_label}}
-    {{/fields}}
+    {{>cpp_for_each_label_body}}
+  }
+
+  template <typename F>
+  void forEachLabel(F f) const {
+    {{>cpp_for_each_label_body}}
   }
 };
 

swift/extractor/SwiftExtractor.cpp

@@ -5,6 +5,7 @@
 #include <unordered_set>
 #include <queue>
 
+#include <picosha2.h>
 #include <swift/AST/SourceFile.h>
 #include <swift/AST/Builtins.h>
 
@@ -14,19 +15,23 @@
 #include "swift/extractor/infra/SwiftLocationExtractor.h"
 #include "swift/extractor/infra/SwiftBodyEmissionStrategy.h"
 #include "swift/extractor/mangler/SwiftMangler.h"
-#include <picosha2.h>
+#include "swift/extractor/infra/log/SwiftAssert.h"
 
 using namespace codeql;
 using namespace std::string_literals;
 namespace fs = std::filesystem;
 
+Logger& main_logger::logger() {
+  static Logger ret{"main"};
+  return ret;
+}
+
+using namespace main_logger;
+
 static void ensureDirectory(const char* label, const fs::path& dir) {
   std::error_code ec;
   fs::create_directories(dir, ec);
-  if (ec) {
-    std::cerr << "Cannot create " << label << " directory: " << ec.message() << "\n";
-    std::abort();
-  }
+  CODEQL_ASSERT(!ec, "Cannot create {} directory ({})", label, ec);
 }
 
 static void archiveFile(const SwiftExtractorConfiguration& config, swift::SourceFile& file) {
@@ -37,10 +42,10 @@ static void archiveFile(const SwiftExtractorConfiguration& config, swift::Source
 
   std::error_code ec;
   fs::copy(source, destination, fs::copy_options::overwrite_existing, ec);
-
   if (ec) {
-    std::cerr << "Cannot archive source file " << source << " -> " << destination << ": "
-              << ec.message() << "\n";
+    LOG_INFO(
+        "Cannot archive source file {} -> {}, probably a harmless race with another process ({})",
+        source, destination, ec);
   }
 }
 
@@ -73,7 +78,7 @@ static fs::path getFilename(swift::ModuleDecl& module,
   if (lazyDeclaration) {
     // this code will be thrown away in the near future
     auto decl = llvm::dyn_cast<swift::ValueDecl>(lazyDeclaration);
-    assert(decl);
+    CODEQL_ASSERT(decl, "not a ValueDecl");
     auto mangled = mangledDeclName(*decl);
     // mangled name can be too long to use as a file name, so we can't use it directly
     mangled = picosha2::hash256_hex_string(mangled);
@@ -276,11 +281,9 @@ void codeql::extractExtractLazyDeclarations(SwiftExtractorState& state,
   // Just in case
   const int upperBound = 100;
   int iteration = 0;
-  while (!state.pendingDeclarations.empty() && iteration++ < upperBound) {
+  while (!state.pendingDeclarations.empty()) {
+    CODEQL_ASSERT(iteration++ < upperBound,
+                  "Swift extractor reached upper bound while extracting lazy declarations");
     extractLazy(state, compiler);
   }
-  if (iteration >= upperBound) {
-    std::cerr << "Swift extractor reached upper bound while extracting lazy declarations\n";
-    abort();
-  }
 }

swift/extractor/SwiftExtractor.h

@@ -8,4 +8,9 @@
 namespace codeql {
 void extractSwiftFiles(SwiftExtractorState& state, swift::CompilerInstance& compiler);
 void extractExtractLazyDeclarations(SwiftExtractorState& state, swift::CompilerInstance& compiler);
+
+class Logger;
+namespace main_logger {
+Logger& logger();
+}
 }  // namespace codeql

swift/extractor/infra/SwiftDispatcher.h

@@ -13,7 +13,7 @@
 #include "swift/extractor/infra/SwiftBodyEmissionStrategy.h"
 #include "swift/extractor/infra/SwiftMangledName.h"
 #include "swift/extractor/config/SwiftExtractorState.h"
-#include "swift/extractor/infra/log/SwiftLogging.h"
+#include "swift/extractor/infra/log/SwiftAssert.h"
 
 namespace codeql {
 
@@ -74,21 +74,20 @@ class SwiftDispatcher {
     entry.forEachLabel([&valid, &entry, this](const char* field, int index, auto& label) {
       using Label = std::remove_reference_t<decltype(label)>;
       if (!label.valid()) {
-        std::cerr << entry.NAME << " has undefined " << field;
-        if (index >= 0) {
-          std::cerr << '[' << index << ']';
-        }
+        const char* action;
         if constexpr (std::is_base_of_v<typename Label::Tag, UnspecifiedElementTag>) {
-          std::cerr << ", replacing with unspecified element\n";
+          action = "replacing with unspecified element";
           label = emitUnspecified(idOf(entry), field, index);
         } else {
-          std::cerr << ", skipping emission\n";
+          action = "skipping emission";
           valid = false;
         }
+        LOG_ERROR("{} has undefined field {}{}, {}", entry.NAME, field,
+                  index >= 0 ? ('[' + std::to_string(index) + ']') : "", action);
       }
     });
     if (valid) {
-      trap.emit(entry);
+      trap.emit(entry, /* check */ false);
     }
   }
 
@@ -153,7 +152,7 @@ class SwiftDispatcher {
     auto& stored = store[e];
     if (!stored.valid()) {
       auto inserted = fetching.insert(e);
-      assert(inserted.second && "detected infinite fetchLabel recursion");
+      CODEQL_ASSERT(inserted.second, "detected infinite fetchLabel recursion");
       stored = createLabel(e, type);
       fetching.erase(e);
     }
@@ -165,7 +164,13 @@ class SwiftDispatcher {
   TrapLabel<TypeTag> fetchLabel(swift::Type t) { return fetchLabel(t.getPointer()); }
 
   TrapLabel<AstNodeTag> fetchLabel(swift::ASTNode node) {
-    return fetchLabelFromUnion<AstNodeTag>(node);
+    auto ret = fetchLabelFromUnion<AstNodeTag>(node);
+    if (!ret.valid()) {
+      // TODO to be more useful, we need a generic way of attaching original source location info
+      // to logs, this will come in upcoming work
+      LOG_ERROR("Unable to fetch label for ASTNode");
+    }
+    return ret;
   }
 
   template <typename E, std::enable_if_t<IsFetchable<E*>>* = nullptr>
@@ -177,7 +182,7 @@ class SwiftDispatcher {
   template <typename E>
   auto createEntry(const E& e) {
     auto found = store.find(&e);
-    assert(found != store.end() && "createEntry called on non-fetched label");
+    CODEQL_ASSERT(found != store.end(), "createEntry called on non-fetched label");
     auto label = TrapLabel<ConcreteTrapTagOf<E>>::unsafeCreateFromUntyped(found->second);
     if constexpr (IsLocatable<E>) {
       locationExtractor.attachLocation(sourceManager, e, label);
@@ -307,7 +312,6 @@ class SwiftDispatcher {
     // with logical op short-circuiting, this will stop trying on the first successful fetch
     bool unionCaseFound = (... || fetchLabelFromUnionCase<Tag, Ts>(u, ret));
     if (!unionCaseFound) {
-      // TODO emit error/warning here
       return undefined_label;
     }
     return ret;
@@ -357,7 +361,10 @@ class SwiftDispatcher {
   SwiftLocationExtractor& locationExtractor;
   SwiftBodyEmissionStrategy& bodyEmissionStrategy;
   std::unordered_set<swift::ModuleDecl*> encounteredModules;
-  Logger logger{"dispatcher"};
+  Logger& logger() {
+    static Logger ret{"dispatcher"};
+    return ret;
+  }
 };
 
 }  // namespace codeql

swift/extractor/infra/file/BUILD.bazel

@@ -2,9 +2,10 @@ load("//swift:rules.bzl", "swift_cc_library")
 
 swift_cc_library(
     name = "file",
-    srcs = glob(["*.cpp"]),
-    hdrs = glob(["*.h"]) + [":path_hash_workaround"],
+    srcs = glob(["*.cpp", "FsLogger.h"]),
+    hdrs = glob(["*.h"], exclude=["FsLogger.h"]) + [":path_hash_workaround"],
     visibility = ["//swift:__subpackages__"],
+    deps = ["//swift/extractor/infra/log"],
 )
 
 genrule(

swift/extractor/infra/file/FsLogger.h

@@ -0,0 +1,10 @@
+#include "swift/extractor/infra/log/SwiftLogging.h"
+
+namespace codeql {
+namespace fs_logger {
+inline Logger& logger() {
+  static Logger ret{"fs"};
+  return ret;
+}
+}  // namespace fs_logger
+}  // namespace codeql

swift/extractor/infra/file/Path.cpp

@@ -1,17 +1,21 @@
 #include "swift/extractor/infra/file/Path.h"
+
 #include <iostream>
 #include <unistd.h>
 
+#include "swift/extractor/infra/file/FsLogger.h"
+
+using namespace std::string_view_literals;
+
 namespace codeql {
 
+using namespace fs_logger;
+
 static bool shouldCanonicalize() {
-  auto preserve = getenv("CODEQL_PRESERVE_SYMLINKS");
-  if (preserve && std::string(preserve) == "true") {
-    return false;
-  }
-  preserve = getenv("SEMMLE_PRESERVE_SYMLINKS");
-  if (preserve && std::string(preserve) == "true") {
-    return false;
+  for (auto var : {"CODEQL_PRESERVE_SYMLINKS", "SEMMLE_PRESERVE_SYMLINKS"}) {
+    if (auto preserve = getenv(var); preserve && preserve == "true"sv) {
+      return false;
+    }
   }
   return true;
 }
@@ -26,8 +30,13 @@ std::filesystem::path resolvePath(const std::filesystem::path& path) {
     ret = std::filesystem::absolute(path, ec);
   }
   if (ec) {
-    std::cerr << "Cannot get " << (canonicalize ? "canonical" : "absolute") << " path: " << path
-              << ": " << ec.message() << "\n";
+    if (ec.value() == ENOENT) {
+      // this is pretty normal, nothing to spam about
+      LOG_DEBUG("resolving non-existing {}", path);
+    } else {
+      LOG_WARNING("cannot get {} path for {} ({})", canonicalize ? "canonical" : "absolute", path,
+                  ec);
+    }
     return path;
   }
   return ret;