Skip to content

Commit

Permalink
Capture logs in tests (#903)
Browse files Browse the repository at this point in the history
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
  • Loading branch information
glbrntt authored Jul 20, 2020
1 parent d4633f2 commit d27c298
Show file tree
Hide file tree
Showing 22 changed files with 271 additions and 75 deletions.
5 changes: 4 additions & 1 deletion Tests/GRPCTests/AnyServiceClientTests.swift
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
13 changes: 8 additions & 5 deletions Tests/GRPCTests/BasicEchoTestCase.swift
Original file line number Diff line number Diff line change
Expand Up @@ -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() {
Expand Down
3 changes: 2 additions & 1 deletion Tests/GRPCTests/CallStartBehaviorTests.swift
Original file line number Diff line number Diff line change
Expand Up @@ -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())
Expand Down
107 changes: 107 additions & 0 deletions Tests/GRPCTests/CapturingLogHandler.swift
Original file line number Diff line number Diff line change
@@ -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
}
}
}
13 changes: 9 additions & 4 deletions Tests/GRPCTests/ClientConnectionBackoffTests.swift
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}
Expand All @@ -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)
}

Expand All @@ -68,6 +72,7 @@ class ClientConnectionBackoffTests: GRPCTestCase {
.withConnectivityStateDelegate(self.connectionStateRecorder)
.withConnectionBackoff(maximum: .milliseconds(100))
.withConnectionTimeout(minimum: .milliseconds(100))
.withBackgroundActivityLogger(self.clientLogger)
}

func testClientConnectionFailsWithNoBackoff() throws {
Expand All @@ -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))
Expand All @@ -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))
Expand All @@ -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))
Expand Down Expand Up @@ -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.
Expand Down
8 changes: 7 additions & 1 deletion Tests/GRPCTests/ClientTLSFailureTests.swift
Original file line number Diff line number Diff line change
Expand Up @@ -62,7 +62,8 @@ class ClientTLSFailureTests: GRPCTestCase {
eventLoopGroup: self.clientEventLoopGroup,
tls: tls,
// No need to retry connecting.
connectionBackoff: nil
connectionBackoff: nil,
backgroundActivityLogger: self.clientLogger
)
}

Expand All @@ -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()

Expand All @@ -97,6 +101,8 @@ class ClientTLSFailureTests: GRPCTestCase {
XCTAssertNoThrow(try self.serverEventLoopGroup.syncShutdownGracefully())
self.server = nil
self.serverEventLoopGroup = nil

super.tearDown()
}

func testClientConnectionFailsWhenServerIsUnknown() throws {
Expand Down
9 changes: 6 additions & 3 deletions Tests/GRPCTests/ClientTLSTests.swift
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand All @@ -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()

Expand All @@ -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()
Expand All @@ -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()

Expand All @@ -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()
Expand Down
7 changes: 5 additions & 2 deletions Tests/GRPCTests/ClientTimeoutTests.swift
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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)

Expand All @@ -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) {
Expand Down
6 changes: 5 additions & 1 deletion Tests/GRPCTests/CompressionTests.swift
Original file line number Diff line number Diff line change
Expand Up @@ -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)
)
}

Expand Down
3 changes: 2 additions & 1 deletion Tests/GRPCTests/ConnectionManagerTests.swift
Original file line number Diff line number Diff line change
Expand Up @@ -27,7 +27,8 @@ class ConnectionManagerTests: GRPCTestCase {
target: .unixDomainSocket("/ignored"),
eventLoopGroup: self.loop,
connectivityStateDelegate: self.recorder,
connectionBackoff: nil
connectionBackoff: nil,
backgroundActivityLogger: self.clientLogger
)
}

Expand Down
Loading

0 comments on commit d27c298

Please sign in to comment.