Improved Logging/Error Handling during SwiftTemplate Processing (#1320)

* Improved logging for SwiftTemplate processing;

Added more logs for time measurement in SwiftTemplate; added a note how exactly cacheKey is calculated and it's intended usage; added possibility to pass Log configuration when using SourceryLib instead of executable for logging setup.

* update internal boilerplate code.

* Fixed failing tests

Sourcery/Configuration.swift

@@ -8,6 +8,7 @@ import TSCBasic
 import Workspace
 import PackageModel
 import SourceryFramework
+import SourceryUtils
 
 public struct Project {
     public let file: XcodeProj

Sourcery/Sourcery.swift

@@ -47,7 +47,18 @@ public class Sourcery {
     fileprivate var fileAnnotatedContent: [Path: [String]] = [:]
 
     /// Creates Sourcery processor
-  public init(verbose: Bool = false, watcherEnabled: Bool = false, cacheDisabled: Bool = false, cacheBasePath: Path? = nil, buildPath: Path? = nil, prune: Bool = false, serialParse: Bool = false, hideVersionHeader: Bool = false, arguments: [String: NSObject] = [:]) {
+    public init(
+        verbose: Bool = false,
+        watcherEnabled: Bool = false,
+        cacheDisabled: Bool = false,
+        cacheBasePath: Path? = nil,
+        buildPath: Path? = nil,
+        prune: Bool = false,
+        serialParse: Bool = false, 
+        hideVersionHeader: Bool = false,
+        arguments: [String: NSObject] = [:],
+        logConfiguration: Log.Configuration? = nil
+    ) {
         self.verbose = verbose
         self.arguments = arguments
         self.watcherEnabled = watcherEnabled
@@ -57,6 +68,9 @@ public class Sourcery {
         self.prune = prune
         self.serialParse = serialParse
         self.hideVersionHeader = hideVersionHeader
+        if let logConfiguration {
+            Log.setup(using: logConfiguration)
+        }
 
         var prefix = Sourcery.generationMarker
         if !hideVersionHeader {

SourceryExecutable/main.swift

@@ -121,15 +121,14 @@ func runCLI() {
         Flag("hideVersionHeader", description: "Do not include Sourcery version in the generated files headers.")
     ) { watcherEnabled, disableCache, verboseLogging, logAST, logBenchmark, parseDocumentation, quiet, prune, serialParse, sources, excludeSources, templates, excludeTemplates, output, isDryRun, configPaths, forceParse, baseIndentation, args, ejsPath, cacheBasePath, buildPath, hideVersionHeader in
         do {
-            Log.stackMessages = isDryRun
-            switch (quiet, verboseLogging) {
-            case (true, _):
-                Log.level = .errors
-            case (false, let isVerbose):
-                Log.level = isVerbose ? .verbose : .info
-            }
-            Log.logBenchmarks = (verboseLogging || logBenchmark) && !quiet
-            Log.logAST = (verboseLogging || logAST) && !quiet
+            let logConfiguration = Log.Configuration(
+                isDryRun: isDryRun,
+                isQuiet: quiet,
+                isVerboseLoggingEnabled: verboseLogging,
+                isLogBenchmarkEnabled: logBenchmark,
+                shouldLogAST: logAST
+            )
+            Log.setup(using: logConfiguration)
 
             // if ejsPath is not provided use default value or executable path
             EJSTemplate.ejsPath = ejsPath.string.isEmpty
@@ -305,15 +304,14 @@ func runCLI() {
         Flag("hideVersionHeader", description: "Do not include Sourcery version in the generated files headers.")
     ) { disableCache, verboseLogging, logAST, logBenchmark, parseDocumentation, quiet, prune, serialParse, sources, excludeSources, templates, excludeTemplates, output, isDryRun, configPaths, forceParse, baseIndentation, args, cacheBasePath, buildPath, hideVersionHeader in
         do {
-            Log.stackMessages = isDryRun
-            switch (quiet, verboseLogging) {
-            case (true, _):
-                Log.level = .errors
-            case (false, let isVerbose):
-                Log.level = isVerbose ? .verbose : .info
-            }
-            Log.logBenchmarks = (verboseLogging || logBenchmark) && !quiet
-            Log.logAST = (verboseLogging || logAST) && !quiet
+            let logConfiguration = Log.Configuration(
+                isDryRun: isDryRun,
+                isQuiet: quiet,
+                isVerboseLoggingEnabled: verboseLogging,
+                isLogBenchmarkEnabled: logBenchmark,
+                shouldLogAST: logAST
+            )
+            Log.setup(using: logConfiguration)
 
             let configurations = configPaths.flatMap { configPath -> [Configuration] in
                 let yamlPath: Path = configPath.isDirectory ? configPath + ".sourcery.yml" : configPath

SourceryRuntime/Sources/Common/Log.swift

@@ -3,6 +3,33 @@ import Foundation
 
 /// :nodoc:
 public enum Log {
+    public struct Configuration {
+        let isDryRun: Bool
+        let isQuiet: Bool
+        let isVerboseLoggingEnabled: Bool
+        let isLogBenchmarkEnabled: Bool
+        let shouldLogAST: Bool
+
+        public init(isDryRun: Bool, isQuiet: Bool, isVerboseLoggingEnabled: Bool, isLogBenchmarkEnabled: Bool, shouldLogAST: Bool) {
+            self.isDryRun = isDryRun
+            self.isQuiet = isQuiet
+            self.isVerboseLoggingEnabled = isVerboseLoggingEnabled
+            self.isLogBenchmarkEnabled = isLogBenchmarkEnabled
+            self.shouldLogAST = shouldLogAST
+        }
+    }
+
+    public static func setup(using configuration: Configuration) {
+        Log.stackMessages = configuration.isDryRun
+        switch (configuration.isQuiet, configuration.isVerboseLoggingEnabled) {
+        case (true, _):
+            Log.level = .errors
+        case (false, let isVerbose):
+            Log.level = isVerbose ? .verbose : .info
+        }
+        Log.logBenchmarks = (configuration.isVerboseLoggingEnabled || configuration.isLogBenchmarkEnabled) && !configuration.isQuiet
+        Log.logAST = (configuration.shouldLogAST) && !configuration.isQuiet
+    }
 
     public enum Level: Int {
         case errors

SourcerySwift/Sources/SourceryRuntime.content.generated.swift

@@ -2022,6 +2022,33 @@ import Foundation
 
 /// :nodoc:
 public enum Log {
+    public struct Configuration {
+        let isDryRun: Bool
+        let isQuiet: Bool
+        let isVerboseLoggingEnabled: Bool
+        let isLogBenchmarkEnabled: Bool
+        let shouldLogAST: Bool
+
+        public init(isDryRun: Bool, isQuiet: Bool, isVerboseLoggingEnabled: Bool, isLogBenchmarkEnabled: Bool, shouldLogAST: Bool) {
+            self.isDryRun = isDryRun
+            self.isQuiet = isQuiet
+            self.isVerboseLoggingEnabled = isVerboseLoggingEnabled
+            self.isLogBenchmarkEnabled = isLogBenchmarkEnabled
+            self.shouldLogAST = shouldLogAST
+        }
+    }
+
+    public static func setup(using configuration: Configuration) {
+        Log.stackMessages = configuration.isDryRun
+        switch (configuration.isQuiet, configuration.isVerboseLoggingEnabled) {
+        case (true, _):
+            Log.level = .errors
+        case (false, let isVerbose):
+            Log.level = isVerbose ? .verbose : .info
+        }
+        Log.logBenchmarks = (configuration.isVerboseLoggingEnabled || configuration.isLogBenchmarkEnabled) && !configuration.isQuiet
+        Log.logAST = (configuration.shouldLogAST) && !configuration.isQuiet
+    }
 
     public enum Level: Int {
         case errors

SourcerySwift/Sources/SourceryRuntime_Linux.content.generated.swift

@@ -2022,6 +2022,33 @@ import Foundation
 
 /// :nodoc:
 public enum Log {
+    public struct Configuration {
+        let isDryRun: Bool
+        let isQuiet: Bool
+        let isVerboseLoggingEnabled: Bool
+        let isLogBenchmarkEnabled: Bool
+        let shouldLogAST: Bool
+
+        public init(isDryRun: Bool, isQuiet: Bool, isVerboseLoggingEnabled: Bool, isLogBenchmarkEnabled: Bool, shouldLogAST: Bool) {
+            self.isDryRun = isDryRun
+            self.isQuiet = isQuiet
+            self.isVerboseLoggingEnabled = isVerboseLoggingEnabled
+            self.isLogBenchmarkEnabled = isLogBenchmarkEnabled
+            self.shouldLogAST = shouldLogAST
+        }
+    }
+
+    public static func setup(using configuration: Configuration) {
+        Log.stackMessages = configuration.isDryRun
+        switch (configuration.isQuiet, configuration.isVerboseLoggingEnabled) {
+        case (true, _):
+            Log.level = .errors
+        case (false, let isVerbose):
+            Log.level = isVerbose ? .verbose : .info
+        }
+        Log.logBenchmarks = (configuration.isVerboseLoggingEnabled || configuration.isLogBenchmarkEnabled) && !configuration.isQuiet
+        Log.logAST = (configuration.shouldLogAST) && !configuration.isQuiet
+    }
 
     public enum Level: Int {
         case errors

SourcerySwift/Sources/SwiftTemplate.swift

@@ -23,16 +23,17 @@ private struct ProcessResult {
 }
 
 open class SwiftTemplate {
-
     public let sourcePath: Path
     let buildPath: Path?
     let cachePath: Path?
-    let code: String
+    let mainFileCodeRaw: String
     let version: String?
     let includedFiles: [Path]
 
     private lazy var buildDir: Path = {
-        let pathComponent = "SwiftTemplate" + (version.map { "/\($0)" } ?? "")
+        var pathComponent = "SwiftTemplate"
+        pathComponent.append("/\(UUID().uuidString)")
+        pathComponent.append((version.map { "/\($0)" } ?? ""))
 
         if let buildPath {
             return (buildPath + pathComponent).absolute()
@@ -42,12 +43,12 @@ open class SwiftTemplate {
         return Path(tempDirURL.path)
     }()
 
-  public init(path: Path, cachePath: Path? = nil, version: String? = nil, buildPath: Path? = nil) throws {
+    public init(path: Path, cachePath: Path? = nil, version: String? = nil, buildPath: Path? = nil) throws {
         self.sourcePath = path
         self.buildPath = buildPath
         self.cachePath = cachePath
         self.version = version
-        (self.code, self.includedFiles) = try SwiftTemplate.parse(sourcePath: path)
+        (self.mainFileCodeRaw, self.includedFiles) = try SwiftTemplate.parse(sourcePath: path)
     }
 
     private enum Command {
@@ -58,9 +59,8 @@ open class SwiftTemplate {
     }
 
     static func parse(sourcePath: Path) throws -> (String, [Path]) {
-
         let commands = try SwiftTemplate.parseCommands(in: sourcePath)
-
+        let startParsing = currentTimestamp()
         var includedFiles: [Path] = []
         var outputFile = [String]()
         var hasContents = false
@@ -99,11 +99,12 @@ open class SwiftTemplate {
 
         \(contents)
         """
-
+        Log.benchmark("\tRaw processing time for \(sourcePath.lastComponent) took: \(currentTimestamp() - startParsing)")
         return (code, includedFiles)
     }
 
     private static func parseCommands(in sourcePath: Path, includeStack: [Path] = []) throws -> [Command] {
+        let startProcessing = currentTimestamp()
         let templateContent = try "<%%>" + sourcePath.read()
 
         let components = templateContent.components(separatedBy: Delimiters.open)
@@ -186,25 +187,35 @@ open class SwiftTemplate {
             }
             processedComponents.append(component)
         }
-
+        Log.benchmark("\tRaw command processing for \(sourcePath.lastComponent) took: \(currentTimestamp() - startProcessing)")
         return commands
     }
 
     public func render(_ context: Any) throws -> String {
         let binaryPath: Path
 
         if let cachePath = cachePath,
-            let hash = cacheKey,
-            let hashPath = hash.addingPercentEncoding(withAllowedCharacters: CharacterSet.alphanumerics) {
-
+           let hash = executableCacheKey,
+           let hashPath = hash.addingPercentEncoding(withAllowedCharacters: CharacterSet.alphanumerics) {
             binaryPath = cachePath + hashPath
-            if !binaryPath.exists {
+            if binaryPath.exists {
+                Log.verbose("Reusing built SwiftTemplate binary for SwiftTemplate with cache key: \(hash)...")
+            } else {
+                Log.verbose("Building new SwiftTemplate binary for SwiftTemplate...")
                 try? cachePath.delete() // clear old cache
                 try cachePath.mkdir()
-                try build().move(binaryPath)
+                do {
+                    try build().move(binaryPath)
+                } catch let error as NSError {
+                    if error.domain == "NSCocoaErrorDomain", error.code == 516 {
+                        Log.warning("This error can be ignored: Attempt to copy `SwiftTemplate` binary to \(binaryPath) failed. Probably multiple Sourcery processes trying to cache into the same directory.")
+                    } else {
+                        throw error
+                    }
+                }
             }
         } else {
-            try binaryPath = build()
+            binaryPath = try build()
         }
 
         let serializedContextPath = buildDir + "context.bin"
@@ -223,6 +234,7 @@ open class SwiftTemplate {
     }
 
     func build() throws -> Path {
+        let startCompiling = currentTimestamp()
         let sourcesDir = buildDir + Path("Sources")
         let templateFilesDir = sourcesDir + Path("SwiftTemplate")
         let mainFile = templateFilesDir + Path("main.swift")
@@ -236,7 +248,7 @@ open class SwiftTemplate {
         if !manifestFile.exists {
             try manifestFile.write(manifestCode)
         }
-        try mainFile.write(code)
+        try mainFile.write(mainFileCodeRaw)
 
         let binaryFile = buildDir + Path(".build/release/SwiftTemplate")
 
@@ -272,7 +284,7 @@ open class SwiftTemplate {
                 .filter { !$0.isEmpty }
                 .joined(separator: "\n")
         }
-
+        Log.benchmark("\tRaw compilation of SwiftTemplate took: \(currentTimestamp() - startCompiling)")
         return binaryFile
     }
 
@@ -320,10 +332,20 @@ open class SwiftTemplate {
         """
     }
 #endif
-    var cacheKey: String? {
-        var contents = code
 
-        // For every included file, make sure that the path and modification date are included in the key
+    /// Brief:
+    ///   - Executable cache key is calculated solely on the contents of the SwiftTemplate ephemeral package.
+    /// Rationale:
+    ///   1. cache key is used to find SwiftTemplate `executable` file from a previous compilation
+    ///   2. `SwiftTemplate` contains types from `SourceryRuntime` and `main.swift`
+    ///   3. `main.swift` in `SwiftTemplate` contains `only .swifttemplate file processing result`
+    ///   4. Copied `includeFile` directives from the given `.swifttemplate` are also included into `SwiftTemplate` ephemeral package
+    ///
+    /// Due to this reason, the correct logic for calculating `executableCacheKey` is to only consider contents of `SwiftTemplate` ephemeral package,
+    /// because `main.swift` is **the only file** which changes in `SwiftTemplate` ephemeral binary, and `includeFiles` are the only files that may
+    /// be changed between executions of Sourcery.
+    var executableCacheKey: String? {
+        var contents = mainFileCodeRaw
         let files = includedFiles.map({ $0.absolute() }).sorted(by: { $0.string < $1.string })
         for file in files {
             let hash = (try? file.read().sha256().base64EncodedString()) ?? ""
@@ -358,7 +380,7 @@ private extension String {
     var stringEncoded: String {
         return self.unicodeScalars.map { x -> String in
             return x.escaped(asASCII: true)
-            }.joined(separator: "")
+        }.joined(separator: "")
     }
 }
 
@@ -410,11 +432,11 @@ private extension Process {
 
 extension String {
     func bridge() -> NSString {
-        #if os(Linux)
-            return NSString(string: self)
-        #else
-            return self as NSString
-        #endif
+#if os(Linux)
+        return NSString(string: self)
+#else
+        return self as NSString
+#endif
     }
 }