Capture logs in tests (#903)

Motivation:

In #902 we changed behaviour such that gRPC will not log unless you
explicitly pass in a logger. When  tests fail it's useful to have the
logs to triage them, especially when they fail under CI, for example.

Modifications:

- Add a capturing log handler factory to the test module which captures
  all logs emitted by handlers it makes
- Wire up loggers in tests
- Hook up `GRPCTestCase` to print the captured logs only if a test fails
  (or an environment variable was set)
- Add a bunch of missing `super.setUp` and `super.tearDown` calls

Result:

- If a test fails we get all `.trace` level logs emitted during that
  test

Author: glbrntt

Tests/GRPCTests/AnyServiceClientTests.swift

@@ -20,7 +20,10 @@ import XCTest
 
 class AnyServiceClientTests: EchoTestCaseBase {
   var anyServiceClient: AnyServiceClient {
-    return AnyServiceClient(channel: self.client.channel)
+    return AnyServiceClient(
+      channel: self.client.channel,
+      defaultCallOptions: self.callOptionsWithLogger
+    )
   }
 
   func testUnary() throws {

Tests/GRPCTests/BasicEchoTestCase.swift

@@ -100,23 +100,26 @@ class EchoTestCaseBase: GRPCTestCase {
     return try self.serverBuilder()
       .withErrorDelegate(makeErrorDelegate())
       .withServiceProviders([makeEchoProvider()])
+      .withLogger(self.serverLogger)
       .bind(host: "localhost", port: 0)
       .wait()
   }
 
   func makeClientConnection(port: Int) throws -> ClientConnection {
-    return self.connectionBuilder().connect(
-      host: "localhost",
-      port: port
-    )
+    return self.connectionBuilder()
+      .withBackgroundActivityLogger(self.clientLogger)
+      .connect(host: "localhost", port: port)
   }
 
   func makeEchoProvider() -> Echo_EchoProvider { return EchoProvider() }
 
   func makeErrorDelegate() -> ServerErrorDelegate? { return nil }
 
   func makeEchoClient(port: Int) throws -> Echo_EchoClient {
-    return Echo_EchoClient(channel: try self.makeClientConnection(port: port))
+    return Echo_EchoClient(
+      channel: try self.makeClientConnection(port: port),
+      defaultCallOptions: self.callOptionsWithLogger
+    )
   }
 
   override func setUp() {

Tests/GRPCTests/CallStartBehaviorTests.swift

@@ -29,12 +29,13 @@ class CallStartBehaviorTests: GRPCTestCase {
     // and the RPC wouldn't complete until we call shutdown (because we're not setting a timeout).
     let channel = ClientConnection.insecure(group: group)
       .withCallStartBehavior(.fastFailure)
+      .withBackgroundActivityLogger(self.clientLogger)
       .connect(host: "http://unreachable.invalid", port: 0)
     defer {
       XCTAssertNoThrow(try channel.close().wait())
     }
 
-    let echo = Echo_EchoClient(channel: channel)
+    let echo = Echo_EchoClient(channel: channel, defaultCallOptions: self.callOptionsWithLogger)
     let get = echo.get(.with { $0.text = "Is anyone out there?" })
 
     XCTAssertThrowsError(try get.response.wait())

Tests/GRPCTests/CapturingLogHandler.swift

@@ -0,0 +1,107 @@
+/*
+ * Copyright 2020, gRPC Authors All rights reserved.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+import struct Foundation.Date
+import Logging
+import NIOConcurrencyHelpers
+
+/// A `LogHandler` factory which captures all logs emitted by the handlers it makes.
+internal class CapturingLogHandlerFactory {
+  private var lock = Lock()
+  private var _logs: [CapturedLog] = []
+
+  /// Returns all captured logs and empties the store of captured logs.
+  func clearCapturedLogs() -> [CapturedLog] {
+    return self.lock.withLock {
+      let logs = self._logs
+      self._logs.removeAll()
+      return logs
+    }
+  }
+
+  /// Make a `LogHandler` whose logs will be recorded by this factory.
+  func make(_ label: String) -> LogHandler {
+    return CapturingLogHandler(label: label) { log in
+      self.lock.withLockVoid {
+        self._logs.append(log)
+      }
+    }
+  }
+}
+
+/// A captured log.
+internal struct CapturedLog {
+  var label: String
+  var level: Logger.Level
+  var message: Logger.Message
+  var metadata: Logger.Metadata
+  var file: String
+  var function: String
+  var line: UInt
+  var date: Date
+}
+
+/// A log handler which captures all logs it records.
+internal struct CapturingLogHandler: LogHandler {
+  private let capture: (CapturedLog) -> Void
+
+  internal let label: String
+  internal var metadata: Logger.Metadata = [:]
+  internal var logLevel: Logger.Level = .trace
+
+  fileprivate init(label: String, capture: @escaping (CapturedLog) -> ()) {
+    self.label = label
+    self.capture = capture
+  }
+
+  internal func log(
+    level: Logger.Level,
+    message: Logger.Message,
+    metadata: Logger.Metadata?,
+    file: String,
+    function: String,
+    line: UInt
+  ) {
+    let merged: Logger.Metadata
+
+    if let metadata = metadata {
+      merged = self.metadata.merging(metadata, uniquingKeysWith: { old, new in return new })
+    } else {
+      merged = self.metadata
+    }
+
+    let log = CapturedLog(
+      label: self.label,
+      level: level,
+      message: message,
+      metadata: merged,
+      file: file,
+      function: function,
+      line: line,
+      date: Date()
+    )
+
+    self.capture(log)
+  }
+
+  internal subscript(metadataKey metadataKey: String) -> Logger.Metadata.Value? {
+    get {
+      return self.metadata[metadataKey]
+    }
+    set {
+      self.metadata[metadataKey] = newValue
+    }
+  }
+}

Tests/GRPCTests/ClientConnectionBackoffTests.swift

@@ -33,6 +33,7 @@ class ClientConnectionBackoffTests: GRPCTestCase {
   var connectionStateRecorder = RecordingConnectivityDelegate()
 
   override func setUp() {
+    super.setUp()
     self.serverGroup = MultiThreadedEventLoopGroup(numberOfThreads: 1)
     self.clientGroup = MultiThreadedEventLoopGroup(numberOfThreads: 1)
   }
@@ -55,11 +56,14 @@ class ClientConnectionBackoffTests: GRPCTestCase {
     XCTAssertNoThrow(try self.clientGroup.syncShutdownGracefully())
     self.client = nil
     self.clientGroup = nil
+
+    super.tearDown()
   }
 
   func makeServer() -> EventLoopFuture<Server> {
     return Server.insecure(group: self.serverGroup)
       .withServiceProviders([EchoProvider()])
+      .withLogger(self.serverLogger)
       .bind(host: "localhost", port: self.port)
   }
 
@@ -68,6 +72,7 @@ class ClientConnectionBackoffTests: GRPCTestCase {
       .withConnectivityStateDelegate(self.connectionStateRecorder)
       .withConnectionBackoff(maximum: .milliseconds(100))
       .withConnectionTimeout(minimum: .milliseconds(100))
+      .withBackgroundActivityLogger(self.clientLogger)
   }
 
   func testClientConnectionFailsWithNoBackoff() throws {
@@ -83,7 +88,7 @@ class ClientConnectionBackoffTests: GRPCTestCase {
       .connect(host: "localhost", port: self.port)
 
     // Start an RPC to trigger creating a channel.
-    let echo = Echo_EchoClient(channel: self.client)
+    let echo = Echo_EchoClient(channel: self.client, defaultCallOptions: self.callOptionsWithLogger)
     _ = echo.get(.with { $0.text = "foo" })
 
     self.connectionStateRecorder.waitForExpectedChanges(timeout: .seconds(5))
@@ -104,7 +109,7 @@ class ClientConnectionBackoffTests: GRPCTestCase {
       .connect(host: "localhost", port: self.port)
 
     // Start an RPC to trigger creating a channel.
-    let echo = Echo_EchoClient(channel: self.client)
+    let echo = Echo_EchoClient(channel: self.client, defaultCallOptions: self.callOptionsWithLogger)
     _ = echo.get(.with { $0.text = "foo" })
 
     self.connectionStateRecorder.waitForExpectedChanges(timeout: .seconds(5))
@@ -123,7 +128,7 @@ class ClientConnectionBackoffTests: GRPCTestCase {
       .connect(host: "localhost", port: self.port)
 
     // Start an RPC to trigger creating a channel.
-    let echo = Echo_EchoClient(channel: self.client)
+    let echo = Echo_EchoClient(channel: self.client, defaultCallOptions: self.callOptionsWithLogger)
     _ = echo.get(.with { $0.text = "foo" })
 
     self.connectionStateRecorder.waitForExpectedChanges(timeout: .seconds(5))
@@ -162,7 +167,7 @@ class ClientConnectionBackoffTests: GRPCTestCase {
       .connect(host: "localhost", port: self.port)
 
     // Start an RPC to trigger creating a channel.
-    let echo = Echo_EchoClient(channel: self.client)
+    let echo = Echo_EchoClient(channel: self.client, defaultCallOptions: self.callOptionsWithLogger)
     _ = echo.get(.with { $0.text = "foo" })
 
     // Wait for the connection to be ready.

Tests/GRPCTests/ClientTLSFailureTests.swift

@@ -62,7 +62,8 @@ class ClientTLSFailureTests: GRPCTestCase {
       eventLoopGroup: self.clientEventLoopGroup,
       tls: tls,
       // No need to retry connecting.
-      connectionBackoff: nil
+      connectionBackoff: nil,
+      backgroundActivityLogger: self.clientLogger
     )
   }
 
@@ -71,13 +72,16 @@ class ClientTLSFailureTests: GRPCTestCase {
   }
 
   override func setUp() {
+    super.setUp()
+
     self.serverEventLoopGroup = MultiThreadedEventLoopGroup(numberOfThreads: 1)
 
     self.server = try! Server.secure(
       group: self.serverEventLoopGroup,
       certificateChain: [SampleCertificate.server.certificate],
       privateKey: SamplePrivateKey.server
     ).withServiceProviders([EchoProvider()])
+      .withLogger(self.serverLogger)
       .bind(host: "localhost", port: 0)
       .wait()
 
@@ -97,6 +101,8 @@ class ClientTLSFailureTests: GRPCTestCase {
     XCTAssertNoThrow(try self.serverEventLoopGroup.syncShutdownGracefully())
     self.server = nil
     self.serverEventLoopGroup = nil
+
+    super.tearDown()
   }
 
   func testClientConnectionFailsWhenServerIsUnknown() throws {

Tests/GRPCTests/ClientTLSTests.swift

@@ -33,15 +33,14 @@ class ClientTLSHostnameOverrideTests: GRPCTestCase {
   }
 
   override func tearDown() {
-    super.tearDown()
     XCTAssertNoThrow(try self.server.close().wait())
     XCTAssertNoThrow(try connection.close().wait())
     XCTAssertNoThrow(try self.eventLoopGroup.syncShutdownGracefully())
+    super.tearDown()
   }
 
-
   func doTestUnary() throws {
-    let client = Echo_EchoClient(channel: self.connection)
+    let client = Echo_EchoClient(channel: self.connection, defaultCallOptions: self.callOptionsWithLogger)
     let get = client.get(.with { $0.text = "foo" })
 
     let response = try get.response.wait()
@@ -59,6 +58,7 @@ class ClientTLSHostnameOverrideTests: GRPCTestCase {
     self.server = try Server.secure(group: self.eventLoopGroup, certificateChain: [cert], privateKey: key)
       .withTLS(trustRoots: .certificates([SampleCertificate.ca.certificate]))
       .withServiceProviders([EchoProvider()])
+      .withLogger(self.serverLogger)
       .bind(host: "localhost", port: 0)
       .wait()
 
@@ -70,6 +70,7 @@ class ClientTLSHostnameOverrideTests: GRPCTestCase {
     self.connection = ClientConnection.secure(group: self.eventLoopGroup)
       .withTLS(trustRoots: .certificates([SampleCertificate.ca.certificate]))
       .withTLS(serverHostnameOverride: "example.com")
+      .withBackgroundActivityLogger(self.clientLogger)
       .connect(host: "localhost", port: port)
 
     try self.doTestUnary()
@@ -83,6 +84,7 @@ class ClientTLSHostnameOverrideTests: GRPCTestCase {
     self.server = try Server.secure(group: self.eventLoopGroup, certificateChain: [cert], privateKey: key)
       .withTLS(trustRoots: .certificates([SampleCertificate.ca.certificate]))
       .withServiceProviders([EchoProvider()])
+      .withLogger(self.serverLogger)
       .bind(host: "localhost", port: 0)
       .wait()
 
@@ -93,6 +95,7 @@ class ClientTLSHostnameOverrideTests: GRPCTestCase {
 
     self.connection = ClientConnection.secure(group: self.eventLoopGroup)
       .withTLS(trustRoots: .certificates([SampleCertificate.ca.certificate]))
+      .withBackgroundActivityLogger(self.clientLogger)
       .connect(host: "localhost", port: port)
 
     try self.doTestUnary()

Tests/GRPCTests/ClientTimeoutTests.swift

@@ -28,7 +28,9 @@ class ClientTimeoutTests: GRPCTestCase {
     // We use a deadline here because internally we convert timeouts into deadlines by diffing
     // with `DispatchTime.now()`. We therefore need the deadline to be known in advance. Note we
     // use zero because `EmbeddedEventLoop`s time starts at zero.
-    return CallOptions(timeLimit: .deadline(.uptimeNanoseconds(0) + timeout))
+    var options = self.callOptionsWithLogger
+    options.timeLimit = .deadline(.uptimeNanoseconds(0) + timeout)
+    return options
   }
 
   // Note: this is not related to the call timeout since we're using an EmbeddedChannel. We require
@@ -38,7 +40,7 @@ class ClientTimeoutTests: GRPCTestCase {
   override func setUp() {
     super.setUp()
 
-    let connection = EmbeddedGRPCChannel()
+    let connection = EmbeddedGRPCChannel(logger: self.clientLogger)
     XCTAssertNoThrow(try connection.embeddedChannel.connect(to: SocketAddress(unixDomainSocketPath: "/foo")))
     let client = Echo_EchoClient(channel: connection, defaultCallOptions: self.callOptions)
 
@@ -48,6 +50,7 @@ class ClientTimeoutTests: GRPCTestCase {
 
   override func tearDown() {
     XCTAssertNoThrow(try self.channel.finish())
+    super.tearDown()
   }
 
   func assertRPCTimedOut(_ response: EventLoopFuture<Echo_EchoResponse>, expectation: XCTestExpectation) {

Tests/GRPCTests/CompressionTests.swift

@@ -29,30 +29,34 @@ class MessageCompressionTests: GRPCTestCase {
   var echo: Echo_EchoClient!
 
   override func setUp() {
+    super.setUp()
     self.group = MultiThreadedEventLoopGroup(numberOfThreads: 1)
   }
 
   override func tearDown() {
     XCTAssertNoThrow(try self.client.close().wait())
     XCTAssertNoThrow(try self.server.close().wait())
     XCTAssertNoThrow(try self.group.syncShutdownGracefully())
+    super.tearDown()
   }
 
   func setupServer(encoding: ServerMessageEncoding) throws {
     self.server = try Server.insecure(group: self.group)
       .withServiceProviders([EchoProvider()])
       .withMessageCompression(encoding)
+      .withLogger(self.serverLogger)
       .bind(host: "localhost", port: 0)
       .wait()
   }
 
   func setupClient(encoding: ClientMessageEncoding) {
     self.client = ClientConnection.insecure(group: self.group)
+      .withBackgroundActivityLogger(self.clientLogger)
       .connect(host: "localhost", port: self.server.channel.localAddress!.port!)
 
     self.echo = Echo_EchoClient(
       channel: self.client,
-      defaultCallOptions: CallOptions(messageEncoding: encoding)
+      defaultCallOptions: CallOptions(messageEncoding: encoding, logger: self.clientLogger)
     )
   }
 

Tests/GRPCTests/ConnectionManagerTests.swift

@@ -27,7 +27,8 @@ class ConnectionManagerTests: GRPCTestCase {
       target: .unixDomainSocket("/ignored"),
       eventLoopGroup: self.loop,
       connectivityStateDelegate: self.recorder,
-      connectionBackoff: nil
+      connectionBackoff: nil,
+      backgroundActivityLogger: self.clientLogger
     )
   }