[ClangImporter] improve structure of swiftify debug logs

This adds automatic scope management and indentation to the logs to make
them more structured. Also adds some additional logging.
Here's an example of what it can look like now:
```
[swiftify:593] Checking 'CountedByProtocol' protocol for methods with bounds and lifetime info
[swiftify:350] | Checking 'simple::' for bounds and lifetime info
[swiftify:411] | | Checking parameter 'len' with type 'int'
[swiftify:411] | | Checking parameter 'p' with type 'int * __counted_by(len)'
[swiftify:435] | | | Found bounds info 'int * __counted_by(len)'
[swiftify:350] | Checking 'shared:::' for bounds and lifetime info
[swiftify:411] | | Checking parameter 'len' with type 'int'
[swiftify:411] | | Checking parameter 'p1' with type 'int * __counted_by(len)'
[swiftify:435] | | | Found bounds info 'int * __counted_by(len)'
[swiftify:411] | | Checking parameter 'p2' with type 'int * __counted_by(len)'
[swiftify:435] | | | Found bounds info 'int * __counted_by(len)'
[swiftify:350] | Checking 'complexExpr:::' for bounds and lifetime info
[swiftify:411] | | Checking parameter 'len' with type 'int'
[swiftify:411] | | Checking parameter 'offset' with type 'int'
[swiftify:411] | | Checking parameter 'p' with type 'int * __counted_by(len - offset)'
[swiftify:435] | | | Found bounds info 'int * __counted_by(len - offset)'
[swiftify:350] | Checking 'nullUnspecified::' for bounds and lifetime info
[swiftify:411] | | Checking parameter 'len' with type 'int'
[swiftify:411] | | Checking parameter 'p' with type 'int * __counted_by(len) _Null_unspecified'
[swiftify:435] | | | Found bounds info 'int * __counted_by(len) _Null_unspecified'
[swiftify:350] | Checking 'nonnull::' for bounds and lifetime info
[swiftify:411] | | Checking parameter 'len' with type 'int'
[swiftify:411] | | Checking parameter 'p' with type 'int * __counted_by(len) _Nonnull'
[swiftify:435] | | | Found bounds info 'int * __counted_by(len) _Nonnull'
[swiftify:350] | Checking 'nullable::' for bounds and lifetime info
[swiftify:411] | | Checking parameter 'len' with type 'int'
[swiftify:411] | | Checking parameter 'p' with type 'int * __counted_by(len) _Nullable'
[swiftify:435] | | | Found bounds info 'int * __counted_by(len) _Nullable'
[swiftify:350] | Checking 'returnPointer:' for bounds and lifetime info
[swiftify:379] | | Found bounds info 'int * __counted_by(len)' on return value
[swiftify:411] | | Checking parameter 'len' with type 'int'
[swiftify:350] | Checking 'staticMethod::' for bounds and lifetime info
[swiftify:411] | | Checking parameter 'len' with type 'int'
[swiftify:411] | | Checking parameter 'p' with type 'int * __counted_by(len)'
[swiftify:435] | | | Found bounds info 'int * __counted_by(len)'
```

Author: hnrklssn

lib/ClangImporter/SwiftifyDecl.cpp

@@ -31,9 +31,38 @@ using namespace swift;
 using namespace importer;
 
 #define DEBUG_TYPE "safe-interop-wrappers"
-#define DLOG(x) LLVM_DEBUG(llvm::dbgs() << x)
+
+#define DLOG(x) LLVM_DEBUG(LogIndentTracker::indent(DBGS) << x)
+
+#ifndef NDEBUG
+#define DBGS llvm::dbgs() << "[swiftify:" << __LINE__ << "] "
+#define DUMP(x) DLOG(""); x->dump()
+#define DLOG_SCOPE(x) DLOG(x); LogIndentTracker Scope
+#else
+#define DLOG_SCOPE(x) do {} while(false);
+#endif
+
 
 namespace {
+#ifndef NDEBUG
+struct LogIndentTracker {
+  static thread_local uint8_t LogIndent;
+  static llvm::raw_ostream &indent(llvm::raw_ostream &out) {
+    for (uint8_t i = 0; i < LogIndent; i++)
+      out << "| ";
+    return out;
+  }
+
+  LogIndentTracker() {
+    LogIndent++;
+  }
+  ~LogIndentTracker() {
+    LogIndent--;
+  }
+};
+thread_local uint8_t LogIndentTracker::LogIndent = 0;
+#endif
+
 ValueDecl *getKnownSingleDecl(ASTContext &SwiftContext, StringRef DeclName) {
   SmallVector<ValueDecl *, 1> decls;
   SwiftContext.lookupInSwiftModule(DeclName, decls);
@@ -196,8 +225,7 @@ struct CountedByExpressionValidator
     case clang::BuiltinType::ULong:
     case clang::BuiltinType::LongLong:
     case clang::BuiltinType::ULongLong:
-      // These integer literals are printed with a suffix that isn't valid Swift
-      // syntax
+      DLOG("Ignoring count parameter with non-portable integer literal");
       return false;
     default:
       return true;
@@ -236,7 +264,10 @@ struct CountedByExpressionValidator
   SUPPORTED_BINOP(Or)
 #undef SUPPORTED_BINOP
 
-  bool VisitStmt(const clang::Stmt *) { return false; }
+  bool VisitStmt(const clang::Stmt *) {
+    DLOG("Ignoring count parameter with unsupported expression\n");
+    return false;
+  }
 };
 
 
@@ -255,16 +286,24 @@ static bool SwiftifiableSizedByPointerType(const clang::ASTContext &ctx,
   if (nonnullType->isOpaquePointer())
     return true;
   PointerTypeKind PTK;
-  if (!nonnullType->getAnyPointerElementType(PTK))
+  if (!nonnullType->getAnyPointerElementType(PTK)) {
+    DLOG("Ignoring sized_by on non-pointer type\n");
     return false;
+  }
   if (PTK == PTK_UnsafeRawPointer || PTK == PTK_UnsafeMutableRawPointer)
     return true;
-  if (PTK != PTK_UnsafePointer && PTK != PTK_UnsafeMutablePointer)
+  if (PTK != PTK_UnsafePointer && PTK != PTK_UnsafeMutablePointer) {
+    DLOG("Ignoring sized_by on Autoreleasing pointer\n");
+    CONDITIONAL_ASSERT(PTK == PTK_AutoreleasingUnsafeMutablePointer);
     return false;
+  }
   // We have a pointer to a type with a size. Verify that it is char-sized.
   auto PtrT = CAT->getAs<clang::PointerType>();
   auto PointeeT = PtrT->getPointeeType();
-  return ctx.getTypeSizeInChars(PointeeT).isOne();
+  bool isByteSized = ctx.getTypeSizeInChars(PointeeT).isOne();
+  if (!isByteSized)
+    DLOG("Ignoring sized_by on non-byte-sized pointer\n");
+  return isByteSized;
 }
 static bool SwiftifiableCAT(const clang::ASTContext &ctx,
                             const clang::CountAttributedType *CAT,
@@ -287,6 +326,7 @@ struct UnaliasedInstantiationVisitor
   bool
   VisitTemplateSpecializationType(const clang::TemplateSpecializationType *) {
     hasUnaliasedInstantiation = true;
+    DLOG("Signature contains raw template, skipping");
     return false;
   }
 };
@@ -325,7 +365,7 @@ static bool swiftifyImpl(ClangImporter::Implementation &Self,
                          SwiftifyInfoFunctionPrinter &printer,
                          const AbstractFunctionDecl *MappedDecl,
                          const T *ClangDecl) {
-  DLOG("Checking " << *ClangDecl << " for bounds and lifetime info\n");
+  DLOG_SCOPE("Checking '" << *ClangDecl << "' for bounds and lifetime info\n");
 
   // FIXME: for private macro generated functions we do not serialize the
   // SILFunction's body anywhere triggering assertions.
@@ -354,20 +394,22 @@ static bool swiftifyImpl(ClangImporter::Implementation &Self,
     auto *CAT = clangReturnTy->getAs<clang::CountAttributedType>();
     if (SwiftifiableCAT(clangASTContext, CAT, swiftReturnTy)) {
       printer.printCountedBy(CAT, SwiftifyInfoPrinter::RETURN_VALUE_INDEX);
-      DLOG("  Found bounds info '" << clang::QualType(CAT, 0) << "' on return value\n");
+      DLOG("Found bounds info '" << clang::QualType(CAT, 0) << "' on return value\n");
       attachMacro = true;
     }
     auto dependsOnClass = [](const ParamDecl *fromParam) {
       return fromParam->getInterfaceType()->isAnyClassReferenceType();
     };
     bool returnHasLifetimeInfo = false;
     if (getImplicitObjectParamAnnotation<clang::LifetimeBoundAttr>(ClangDecl)) {
-      DLOG("  Found lifetimebound attribute on implicit 'this'\n");
+      DLOG("Found lifetimebound attribute on implicit 'this'\n");
       if (!dependsOnClass(
               MappedDecl->getImplicitSelfDecl(/*createIfNeeded*/ true))) {
         printer.printLifetimeboundReturn(SwiftifyInfoPrinter::SELF_PARAM_INDEX,
                                          true);
         returnHasLifetimeInfo = true;
+      } else {
+        DLOG("lifetimebound ignored because it depends on class with refcount\n");
       }
     }
 
@@ -385,6 +427,8 @@ static bool swiftifyImpl(ClangImporter::Implementation &Self,
                                 : getNumParams(ClangDecl);
     for (auto [index, clangParam] : llvm::enumerate(ClangDecl->parameters())) {
       clang::QualType clangParamTy = clangParam->getType();
+      DLOG_SCOPE("Checking parameter '" << *clangParam << "' with type '"
+                                        << clangParamTy << "'\n");
       int mappedIndex = index < selfParamIndex ? index :
         index > selfParamIndex ? index - 1 :
         SwiftifyInfoPrinter::SELF_PARAM_INDEX;
@@ -408,8 +452,7 @@ static bool swiftifyImpl(ClangImporter::Implementation &Self,
                  diag::note_swift_name_instance_method);
       } else if (SwiftifiableCAT(clangASTContext, CAT, swiftParamTy)) {
         printer.printCountedBy(CAT, mappedIndex);
-        DLOG("  Found bounds info '" << clangParamTy << "' on parameter '"
-                                     << *clangParam << "'\n");
+        DLOG("Found bounds info '" << clangParamTy << "'\n");
         attachMacro = paramHasBoundsInfo = true;
       }
       bool paramIsStdSpan =
@@ -418,13 +461,12 @@ static bool swiftifyImpl(ClangImporter::Implementation &Self,
 
       bool paramHasLifetimeInfo = false;
       if (clangParam->template hasAttr<clang::NoEscapeAttr>()) {
-        DLOG("  Found noescape attribute on parameter '" << *clangParam << "'\n");
+        DLOG("Found noescape attribute\n");
         printer.printNonEscaping(mappedIndex);
         paramHasLifetimeInfo = true;
       }
       if (clangParam->template hasAttr<clang::LifetimeBoundAttr>()) {
-        DLOG("  Found lifetimebound attribute on parameter '" << *clangParam
-                                                              << "'\n");
+        DLOG("Found lifetimebound attribute\n");
         if (!dependsOnClass(swiftParam)) {
           // If this parameter has bounds info we will tranform it into a Span,
           // so then it will no longer be Escapable.
@@ -435,16 +477,17 @@ static bool swiftifyImpl(ClangImporter::Implementation &Self,
           printer.printLifetimeboundReturn(mappedIndex, willBeEscapable);
           paramHasLifetimeInfo = true;
           returnHasLifetimeInfo = true;
+        } else {
+          DLOG("lifetimebound ignored because it depends on class with refcount\n");
         }
       }
       if (paramIsStdSpan && paramHasLifetimeInfo) {
-        DLOG("  Found both std::span and lifetime info for parameter '"
-             << *clangParam << "'\n");
+        DLOG("Found both std::span and lifetime info\n");
         attachMacro = true;
       }
     }
     if (returnIsStdSpan && returnHasLifetimeInfo) {
-      DLOG("  Found both std::span and lifetime info for return value\n");
+      DLOG("Found both std::span and lifetime info for return value\n");
       attachMacro = true;
     }
   }
@@ -501,6 +544,11 @@ void ClangImporter::Implementation::swiftify(AbstractFunctionDecl *MappedDecl) {
   if (!ClangDecl)
     return;
 
+  DLOG_SCOPE(
+      "Checking '" << *ClangDecl << "' (imported as '"
+                   << MappedDecl->getName().getBaseName().userFacingName()
+                   << "')\n");
+
   {
     UnaliasedInstantiationVisitor visitor;
     visitor.TraverseType(ClangDecl->getType());
@@ -509,8 +557,10 @@ void ClangImporter::Implementation::swiftify(AbstractFunctionDecl *MappedDecl) {
   }
 
   MacroDecl *SwiftifyImportDecl = dyn_cast_or_null<MacroDecl>(getKnownSingleDecl(SwiftContext, "_SwiftifyImport"));
-  if (!SwiftifyImportDecl)
+  if (!SwiftifyImportDecl) {
+    DLOG("_SwiftifyImport macro not found");
     return;
+  }
 
   llvm::SmallString<128> MacroString;
   {
@@ -520,8 +570,10 @@ void ClangImporter::Implementation::swiftify(AbstractFunctionDecl *MappedDecl) {
     llvm::StringMap<std::string> typeMapping;
     SwiftifyInfoFunctionPrinter printer(getClangASTContext(), SwiftContext, out,
                                         *SwiftifyImportDecl, typeMapping);
-    if (!swiftifyImpl(*this, printer, MappedDecl, ClangDecl))
+    if (!swiftifyImpl(*this, printer, MappedDecl, ClangDecl)) {
+      DLOG("No relevant bounds or lifetime info found\n");
       return;
+    }
     printer.printAvailability();
     printer.printTypeMapping();
     out << ")";
@@ -557,10 +609,13 @@ void ClangImporter::Implementation::swiftifyProtocol(
 
   MacroDecl *SwiftifyImportDecl = dyn_cast_or_null<MacroDecl>(
       getKnownSingleDecl(SwiftContext, "_SwiftifyImportProtocol"));
-  if (!SwiftifyImportDecl)
+  if (!SwiftifyImportDecl) {
+    DLOG("_SwiftifyImportProtocol macro not found");
     return;
+  }
 
-  DLOG("Checking " << MappedDecl->getName() << " protocol for methods with bounds and lifetime info\n");
+  DLOG_SCOPE("Checking '" << MappedDecl->getName()
+              << "' protocol for methods with bounds and lifetime info\n");
   llvm::SmallString<128> MacroString;
   {
     llvm::raw_svector_ostream out(MacroString);
@@ -579,8 +634,10 @@ void ClangImporter::Implementation::swiftifyProtocol(
       hasBoundsAttributes |= printer.printMethod(SwiftDecl);
     }
 
-    if (!hasBoundsAttributes)
+    if (!hasBoundsAttributes) {
+      DLOG("No relevant bounds or lifetime info found\n");
       return;
+    }
     printer.printAvailability();
     printer.printTypeMapping();
     out << ")";