Add an extra-debug mode DD_TRACE_DEBUG_CALLSTACK , that also prints callstacks after each log message

Author: Nacho Bonafonte

Sources/DatadogSDKTesting/DDEnvironmentValues.swift

@@ -35,6 +35,7 @@ internal enum ConfigurationValues: String, CaseIterable {
     case DD_ENDPOINT
     case DD_DONT_EXPORT
     case DD_TRACE_DEBUG
+    case DD_TRACE_DEBUG_CALLSTACK
 }
 
 // These configuration values must not be passed to the child app in an UI test
@@ -134,6 +135,7 @@ internal struct DDEnvironmentValues {
 
     /// The framework has been launched with extra debug information
     let extraDebug: Bool
+    let extraDebugCallstack: Bool
 
     /// Intelligent test runner related environment
     let gitUploadEnabled: Bool
@@ -288,8 +290,11 @@ internal struct DDEnvironmentValues {
         let envReportHostname = DDEnvironmentValues.getEnvVariable(ExtraConfigurationValues.DD_CIVISIBILITY_REPORT_HOSTNAME.rawValue) as NSString?
         reportHostname = envReportHostname?.boolValue ?? false
 
+        let envExtraDebugCallStack = DDEnvironmentValues.getEnvVariable(ConfigurationValues.DD_TRACE_DEBUG_CALLSTACK.rawValue) as NSString?
+        extraDebugCallstack = envExtraDebugCallStack?.boolValue ?? false
+
         let envExtraDebug = DDEnvironmentValues.getEnvVariable(ConfigurationValues.DD_TRACE_DEBUG.rawValue) as NSString?
-        extraDebug = envExtraDebug?.boolValue ?? false
+        extraDebug = envExtraDebug?.boolValue ?? extraDebugCallstack
 
         /// CI  values
         var branchEnv: String?

Sources/DatadogSDKTesting/DDTestModule.swift

@@ -99,7 +99,7 @@ public class DDTestModule: NSObject, Encodable {
         Log.debug("Module loading time interval: \(DDTestMonitor.clock.now.timeIntervalSince(beforeLoadingTime))")
     }
 
-    func internalEnd(endTime: Date? = nil) {
+    private func internalEnd(endTime: Date? = nil) {
         if DDTestMonitor.instance?.crashedModuleInfo != nil && anyTestExecuted == false {
             //The module started after a crash and no test was executed because of ITR dont report it
             DDTestMonitor.tracer.flush()

Sources/DatadogSDKTesting/DDTestObserver.swift

@@ -30,17 +30,20 @@ class DDTestObserver: NSObject, XCTestObservation {
 
     func testBundleWillStart(_ testBundle: Bundle) {
         let bundleName = testBundle.bundleURL.deletingPathExtension().lastPathComponent
+        Log.debug("testBundleWillStart: \(bundleName)")
         module = DDTestModule.start(bundleName: bundleName)
         module?.testFramework = "XCTest"
     }
 
     func testBundleDidFinish(_ testBundle: Bundle) {
         /// We need to wait for all the traces to be written to the backend before exiting
         module?.end()
+        Log.debug("testBundleDidFinish: \(testBundle.bundleURL.deletingPathExtension().lastPathComponent)")
     }
 
     func testSuiteWillStart(_ testSuite: XCTestSuite) {
         if module?.configError ?? false {
+            Log.debug("testSuiteWillStart: Failed, module config error")
             testSuite.testRun?.stop()
             exit(1)
         }
@@ -51,7 +54,6 @@ class DDTestObserver: NSObject, XCTestObservation {
         else {
             return
         }
-
         Log.measure(name: "waiting itrWorkQueue") {
             DDTestMonitor.instance?.itrWorkQueue.waitUntilAllOperationsAreFinished()
         }
@@ -62,6 +64,7 @@ class DDTestObserver: NSObject, XCTestObservation {
             testSuite.setValue(finalTests, forKey: "_mutableTests")
             if !finalTests.isEmpty {
                 suite = module.suiteStart(name: testSuite.name)
+                Log.debug("testSuiteWillStart: \(testSuite.name)")
             }
             let testsToSkip = tests.count - finalTests.count
             Log.print("ITR skipped \(testsToSkip) tests")
@@ -70,6 +73,7 @@ class DDTestObserver: NSObject, XCTestObservation {
             }
         } else {
             suite = module.suiteStart(name: testSuite.name)
+            Log.debug("testSuiteWillStart: \(testSuite.name)")
         }
     }
 
@@ -78,6 +82,7 @@ class DDTestObserver: NSObject, XCTestObservation {
            tests.firstObject is XCTestCase
         {
             suite?.end()
+            Log.debug("testSuiteDidFinish: \(testSuite.name)")
         }
     }
 

Sources/DatadogSDKTesting/DDTestSuite.swift

@@ -38,7 +38,7 @@ public class DDTestSuite: NSObject, Encodable {
         }
     }
 
-    func internalEnd(endTime: Date? = nil) {
+    private func internalEnd(endTime: Date? = nil) {
         duration = (endTime ?? DDTestMonitor.clock.now).timeIntervalSince(startTime).toNanoseconds
         /// Export module event
 

Sources/DatadogSDKTesting/ImageSymbols/DDSymbolicator.swift

@@ -295,11 +295,15 @@ enum DDSymbolicator {
         Spawn.commandToFile("/usr/bin/symbols -fullSourcePath -lazy \"\(imagePath)\"", outputPath: symbolsOutputURL.path)
         return symbolsOutputURL
     }
-    
 
-    static func getCallStack() -> [String] {
+    static func getCallStack(hidesLibrarySymbols: Bool = true) -> [String] {
         let callStackSymbols = Thread.callStackSymbols
-        let index = callStackSymbols.firstIndex { !$0.contains(exactWord: "DatadogSDKTesting") } ?? 0
+        let index: Array<String>.Index
+        if hidesLibrarySymbols {
+            index = callStackSymbols.firstIndex { !$0.contains(exactWord: "DatadogSDKTesting") } ?? callStackSymbols.startIndex
+        } else {
+            index = callStackSymbols.index(0, offsetBy: 2)
+        }
 
         let demangled: [String] = callStackSymbols.dropFirst(index)
             .map {

Sources/DatadogSDKTesting/Utils/Log.swift

@@ -9,6 +9,7 @@ import Foundation
 
 struct Log {
     private static var debugTracer = DDTestMonitor.env.extraDebug
+    private static var debugTracerCallstack = DDTestMonitor.env.extraDebugCallstack
 
     private static func swiftPrint(_ string: String) {
         Swift.print(string)
@@ -18,7 +19,7 @@ struct Log {
         NSLog(string)
     }
 
-    private static var printMethod: () -> (String) -> () = {
+    private static var printMethod: () -> (String) -> Void = {
         let osActivityMode = DDEnvironmentValues.getEnvVariable("OS_ACTIVITY_MODE") ?? ""
         if osActivityMode == "disable" {
             return swiftPrint
@@ -30,6 +31,9 @@ struct Log {
     static func debug(_ string: @autoclosure () -> String) {
         if debugTracer {
             Log.printMethod()("[Debug][DatadogSDKTesting] " + string() + "\n")
+            if debugTracerCallstack {
+                Swift.print("Callstack:\n" + DDSymbolicator.getCallStack(hidesLibrarySymbols: false).joined(separator: "\n") + "\n")
+            }
         }
     }