Don't delay logging until the end of test when GRPC_ALWAYS_LOG is enabled (#979)

Motivation:

In the tests we capture all emitted logs and print them if a test fails,
or if the "GRPC_ALWAYS_LOG" environment variable is set. However, in the
latter case we will only print the logs if test execution completes; we
get no logs in the case of wedged or crashing tests.

Modifications:

- Extract log formatting into 'CapturedLogFormatter'
- Add an option to the 'CapturingLogHandlerFactory' to allow logs to be
  print when captured
- Only emit logs at the end of test if 'GRPC_ALWAYS_LOG' is disabled and
  the test fails.

Result:

When 'GRPC_ALWAYS_LOG' is enabled, logs will be printed as they are
caught.

Tests/GRPCTests/CapturingLogHandler.swift

@@ -14,6 +14,7 @@
  * limitations under the License.
  */
 import struct Foundation.Date
+import class Foundation.DateFormatter
 import Logging
 import NIOConcurrencyHelpers
 
@@ -22,6 +23,16 @@ internal class CapturingLogHandlerFactory {
   private var lock = Lock()
   private var _logs: [CapturedLog] = []
 
+  private var logFormatter: CapturedLogFormatter?
+
+  init(printWhenCaptured: Bool) {
+    if printWhenCaptured {
+      self.logFormatter = CapturedLogFormatter()
+    } else {
+      self.logFormatter = nil
+    }
+  }
+
   /// Returns all captured logs and empties the store of captured logs.
   func clearCapturedLogs() -> [CapturedLog] {
     return self.lock.withLock {
@@ -37,6 +48,11 @@ internal class CapturingLogHandlerFactory {
       self.lock.withLockVoid {
         self._logs.append(log)
       }
+
+      // If we have a formatter, print the log as well.
+      if let formatter = self.logFormatter {
+        print(formatter.string(for: log))
+      }
     }
   }
 }
@@ -108,3 +124,47 @@ internal struct CapturingLogHandler: LogHandler {
     }
   }
 }
+
+struct CapturedLogFormatter {
+  private var dateFormatter: DateFormatter
+
+  init() {
+    self.dateFormatter = DateFormatter()
+    // We don't care about the date.
+    self.dateFormatter.dateFormat = "HH:mm:ss.SSS"
+  }
+
+  func string(for log: CapturedLog) -> String {
+    let date = self.dateFormatter.string(from: log.date)
+    let level = log.level.short
+
+    // Format the metadata.
+    let formattedMetadata = log.metadata
+      .sorted(by: { $0.key < $1.key })
+      .map { key, value in "\(key)=\(value)" }
+      .joined(separator: " ")
+
+    return "\(date) \(level) \(log.label): \(log.message) { \(formattedMetadata) }"
+  }
+}
+
+extension Logger.Level {
+  fileprivate var short: String {
+    switch self {
+    case .info:
+      return "I"
+    case .debug:
+      return "D"
+    case .warning:
+      return "W"
+    case .error:
+      return "E"
+    case .critical:
+      return "C"
+    case .trace:
+      return "T"
+    case .notice:
+      return "N"
+    }
+  }
+}

Tests/GRPCTests/GRPCTestCase.swift

@@ -32,7 +32,7 @@ class GRPCTestCase: XCTestCase {
 
   override func setUp() {
     super.setUp()
-    self.logFactory = CapturingLogHandlerFactory()
+    self.logFactory = CapturingLogHandlerFactory(printWhenCaptured: GRPCTestCase.alwaysLog)
   }
 
   override func tearDown() {
@@ -48,7 +48,9 @@ class GRPCTestCase: XCTestCase {
       XCTAssertEqual(log.source, "GRPC", "Incorrect log source in \(log.file) on line \(log.line)")
     }
 
-    if GRPCTestCase.alwaysLog || (self.testRun.map { $0.totalFailureCount > 0 } ?? false) {
+    // Only print logs when there's a failure and we're *not* always logging (when we are always
+    // logging, logs will be printed as they're caught).
+    if !GRPCTestCase.alwaysLog, (self.testRun.map { $0.totalFailureCount > 0 } ?? false) {
       self.printCapturedLogs(logs)
     }
 
@@ -99,24 +101,12 @@ class GRPCTestCase: XCTestCase {
 
   /// Prints all captured logs.
   private func printCapturedLogs(_ logs: [CapturedLog]) {
-    let formatter = DateFormatter()
-    // We don't care about the date.
-    formatter.dateFormat = "HH:mm:ss.SSS"
-
     print("Test Case '\(self.name)' logs started")
 
     // The logs are already sorted by date.
+    let formatter = CapturedLogFormatter()
     for log in logs {
-      let date = formatter.string(from: log.date)
-      let level = log.level.short
-
-      // Format the metadata.
-      let formattedMetadata = log.metadata
-        .sorted(by: { $0.key < $1.key })
-        .map { key, value in "\(key)=\(value)" }
-        .joined(separator: " ")
-
-      print("\(date) \(log.label) \(level):", log.message, "{", formattedMetadata, "}")
+      print(formatter.string(for: log))
     }
 
     print("Test Case '\(self.name)' logs finished")
@@ -135,24 +125,3 @@ extension Bool {
     }
   }
 }
-
-extension Logger.Level {
-  fileprivate var short: String {
-    switch self {
-    case .info:
-      return "I"
-    case .debug:
-      return "D"
-    case .warning:
-      return "W"
-    case .error:
-      return "E"
-    case .critical:
-      return "C"
-    case .trace:
-      return "T"
-    case .notice:
-      return "N"
-    }
-  }
-}