Reduce logging verbosity (#632)

Motivation:

The gRPC client and server log a lot. Too much at info level anyway.

Modifications:

- remove unnecessary logs
- lower the priorty of most log messages

Result:

At info level the client and server will only log (in the happy case):
- start and end of rpcs (access logs)
- connectivity state changes (client only)

Sources/GRPC/CallHandlers/BidirectionalStreamingCallHandler.swift

@@ -32,7 +32,7 @@ public class BidirectionalStreamingCallHandler<RequestMessage: Message, Response
 
   private var observerState: ClientStreamingHandlerObserverState<EventObserverFactory, EventObserver> {
     willSet(newState) {
-      self.logger.info("observerState changed from \(self.observerState) to \(newState)")
+      self.logger.debug("observerState changed from \(self.observerState) to \(newState)")
     }
   }
   private var callContext: Context?

Sources/GRPC/CallHandlers/ClientStreamingCallHandler.swift

@@ -40,7 +40,7 @@ public class ClientStreamingCallHandler<RequestMessage: Message, ResponseMessage
 
   private var observerState: ClientStreamingHandlerObserverState<EventObserverFactory, EventObserver> {
     willSet(newState) {
-      self.logger.info("observerState changed from \(self.observerState) to \(newState)")
+      self.logger.debug("observerState changed from \(self.observerState) to \(newState)")
     }
   }
   private var callContext: UnaryResponseCallContext<ResponseMessage>?

Sources/GRPC/ClientCalls/BaseClientCall.swift

@@ -113,7 +113,7 @@ public class BaseClientCall<Request: Message, Response: Message>: ClientCall {
     self.subchannel.whenComplete {
       switch $0 {
       case .success(let channel):
-        self.logger.debug("firing .cancelled event")
+        self.logger.trace("firing .cancelled event")
         channel.pipeline.triggerUserOutboundEvent(GRPCClientUserEvent.cancelled, promise: promise)
       case .failure(let error):
         promise?.fail(error)
@@ -123,7 +123,7 @@ public class BaseClientCall<Request: Message, Response: Message>: ClientCall {
 
   public func cancel() -> EventLoopFuture<Void> {
     return self.subchannel.flatMap { channel in
-      self.logger.debug("firing .cancelled event")
+      self.logger.trace("firing .cancelled event")
       return channel.pipeline.triggerUserOutboundEvent(GRPCClientUserEvent.cancelled)
     }
   }

Sources/GRPC/ClientCalls/BidirectionalStreamingCall.swift

@@ -43,7 +43,7 @@ public final class BidirectionalStreamingCall<RequestMessage: Message, ResponseM
     let requestID = callOptions.requestIDProvider.requestID()
 
     let logger = Logger(subsystem: .clientChannelCall, metadata: [MetadataKey.requestID: "\(requestID)"])
-    logger.info("making bidirectional streaming call to '\(path)', request type: \(RequestMessage.self), response type: \(ResponseMessage.self)")
+    logger.info("starting rpc", metadata: ["path": "\(path)"])
 
     let responseHandler = GRPCClientStreamingResponseChannelHandler(
       initialMetadataPromise: connection.channel.eventLoop.makePromise(),

Sources/GRPC/ClientCalls/ClientStreamingCall.swift

@@ -43,7 +43,7 @@ public final class ClientStreamingCall<RequestMessage: Message, ResponseMessage:
   ) {
     let requestID = callOptions.requestIDProvider.requestID()
     let logger = Logger(subsystem: .clientChannelCall, metadata: [MetadataKey.requestID: "\(requestID)"])
-    logger.info("making client streaming call to '\(path)', request type: \(RequestMessage.self), response type: \(ResponseMessage.self)")
+    logger.info("starting rpc", metadata: ["path": "\(path)"])
 
     self.messageQueue = connection.eventLoop.makeSucceededFuture(())
     let responsePromise = connection.eventLoop.makePromise(of: ResponseMessage.self)

Sources/GRPC/ClientCalls/ServerStreamingCall.swift

@@ -35,7 +35,7 @@ public final class ServerStreamingCall<RequestMessage: Message, ResponseMessage:
   ) {
     let requestID = callOptions.requestIDProvider.requestID()
     let logger = Logger(subsystem: .clientChannelCall, metadata: [MetadataKey.requestID: "\(requestID)"])
-    logger.info("making server streaming call to '\(path)', request type: \(RequestMessage.self), response type: \(ResponseMessage.self)")
+    logger.info("starting rpc", metadata: ["path": "\(path)"])
 
     let responseHandler = GRPCClientStreamingResponseChannelHandler(
       initialMetadataPromise: connection.channel.eventLoop.makePromise(),

Sources/GRPC/ClientCalls/UnaryCall.swift

@@ -41,7 +41,7 @@ public final class UnaryCall<RequestMessage: Message, ResponseMessage: Message>
   ) {
     let requestID = callOptions.requestIDProvider.requestID()
     let logger = Logger(subsystem: .clientChannelCall, metadata: [MetadataKey.requestID: "\(requestID)"])
-    logger.info("making unary call to '\(path)', request type: \(RequestMessage.self), response type: \(ResponseMessage.self)")
+    logger.info("starting rpc", metadata: ["path": "\(path)"])
 
     let responsePromise = connection.channel.eventLoop.makePromise(of: ResponseMessage.self)
     self.response = responsePromise.futureResult

Sources/GRPC/ClientConnection.swift

@@ -66,7 +66,7 @@ import Logging
 /// delegated error handler which uses the error delegate associated with this connection
 /// (see `DelegatingErrorHandler`).
 ///
-/// See `BaseClientCall` for a description of the pipelines assoicated with each HTTP/2 stream.
+/// See `BaseClientCall` for a description of the pipelines associated with each HTTP/2 stream.
 public class ClientConnection {
   internal let logger: Logger
   /// The UUID of this connection, used for logging.
@@ -213,7 +213,7 @@ extension ClientConnection {
     channel.flatMap { $0.closeFuture }.whenComplete { result in
       switch result {
       case .success:
-        self.logger.info("client connection shutdown successfully")
+        self.logger.debug("client connection shutdown successfully")
       case .failure(let error):
         self.logger.warning(
           "client connection shutdown failed",
@@ -275,7 +275,7 @@ extension ClientConnection {
       return configuration.eventLoopGroup.next().makeFailedFuture(GRPCStatus.processingError)
     }
 
-    logger.info("attempting to connect to \(configuration.target)")
+    logger.debug("attempting to connect to \(configuration.target)")
     connectivity.state = .connecting
     let timeoutAndBackoff = backoffIterator?.next()
 
@@ -298,7 +298,7 @@ extension ClientConnection {
     // If we don't have backoff then we can't retry, just return the `channel` no matter what
     // state we are in.
     guard let backoff = timeoutAndBackoff?.backoff else {
-      logger.info("backoff exhausted, no more connection attempts will be made")
+      logger.debug("backoff exhausted, no more connection attempts will be made")
       return channel
     }
 
@@ -327,7 +327,7 @@ extension ClientConnection {
     backoffIterator: ConnectionBackoffIterator?,
     logger: Logger
   ) -> EventLoopFuture<Channel> {
-    logger.info("scheduling connection attempt in \(timeout) seconds")
+    logger.debug("scheduling connection attempt in \(timeout) seconds")
     // The `futureResult` of the scheduled task is of type
     // `EventLoopFuture<EventLoopFuture<Channel>>`, so we need to `flatMap` it to
     // remove a level of indirection.
@@ -387,10 +387,10 @@ extension ClientConnection {
       }
 
     if let timeout = timeout {
-      logger.info("setting connect timeout to \(timeout) seconds")
+      logger.debug("setting connect timeout to \(timeout) seconds")
       return bootstrap.connectTimeout(.seconds(timeInterval: timeout))
     } else {
-      logger.info("no connect timeout provided")
+      logger.debug("no connect timeout provided")
       return bootstrap
     }
   }

Sources/GRPC/ConnectivityState.swift

@@ -87,7 +87,7 @@ public class ConnectivityStateMonitor {
   /// Updates `_state` to `newValue`.
   ///
   /// If the user has initiated shutdown then state updates are _ignored_. This may happen if the
-  /// connection is being estabilshed as the user initiates shutdown.
+  /// connection is being established as the user initiates shutdown.
   ///
   /// - Important: This is **not** thread safe.
   private func setNewState(to newValue: ConnectivityState) {

Sources/GRPC/GRPCChannelHandler.swift

@@ -60,7 +60,7 @@ public final class GRPCChannelHandler {
   public init(servicesByName: [String: CallHandlerProvider], errorDelegate: ServerErrorDelegate?, logger: Logger) {
     self.servicesByName = servicesByName
     self.errorDelegate = errorDelegate
-    self.logger = logger.addingMetadata(key: MetadataKey.channelHandler, value: "GRPCChannelHandler")
+    self.logger = logger
   }
 }
 
@@ -86,12 +86,12 @@ extension GRPCChannelHandler: ChannelInboundHandler, RemovableChannelHandler {
         return
       }
 
-      logger.info("received request head, configuring pipeline")
+      logger.debug("received request head, configuring pipeline")
 
       let codec = callHandler.makeGRPCServerCodec()
       let handlerRemoved: EventLoopPromise<Void> = context.eventLoop.makePromise()
       handlerRemoved.futureResult.whenSuccess {
-        self.logger.info("removed GRPCChannelHandler from pipeline")
+        self.logger.debug("removed GRPCChannelHandler from pipeline")
         context.pipeline.addHandler(callHandler, position: .after(codec)).whenComplete { _ in
           // Send the .headers event back to begin the headers flushing for the response.
           // At this point, which headers should be returned is not known, as the content type is
@@ -103,7 +103,7 @@ extension GRPCChannelHandler: ChannelInboundHandler, RemovableChannelHandler {
         }
       }
 
-      logger.info("adding handler \(type(of: codec)) to pipeline")
+      logger.debug("adding handler \(type(of: codec)) to pipeline")
       context.pipeline.addHandler(codec, position: .after(self))
         .whenSuccess { context.pipeline.removeHandler(context: context, promise: handlerRemoved) }
 
@@ -121,7 +121,7 @@ extension GRPCChannelHandler: ChannelInboundHandler, RemovableChannelHandler {
     // - uriComponents[1]: service name (including the package name);
     //     `CallHandlerProvider`s should provide the service name including the package name.
     // - uriComponents[2]: method name.
-    self.logger.info("making call handler", metadata: ["path": "\(requestHead.uri)"])
+    self.logger.debug("making call handler", metadata: ["path": "\(requestHead.uri)"])
     let uriComponents = requestHead.uri.components(separatedBy: "/")
 
     var logger = self.logger

Sources/GRPC/GRPCClientChannelHandler.swift

@@ -220,13 +220,13 @@ public final class GRPCClientChannelHandler<Request: Message, Response: Message>
     self.logger = logger
     switch callType {
     case .unary:
-      self.stateMachine = .init(requestArity: .one, responseArity: .one, logger: logger)
+      self.stateMachine = .init(requestArity: .one, responseArity: .one)
     case .clientStreaming:
-      self.stateMachine = .init(requestArity: .many, responseArity: .one, logger: logger)
+      self.stateMachine = .init(requestArity: .many, responseArity: .one)
     case .serverStreaming:
-      self.stateMachine = .init(requestArity: .one, responseArity: .many, logger: logger)
+      self.stateMachine = .init(requestArity: .one, responseArity: .many)
     case .bidirectionalStreaming:
-      self.stateMachine = .init(requestArity: .many, responseArity: .many, logger: logger)
+      self.stateMachine = .init(requestArity: .many, responseArity: .many)
     }
   }
 }

Sources/GRPC/GRPCClientResponseChannelHandler.swift

@@ -27,6 +27,7 @@ import Logging
 internal class GRPCClientResponseChannelHandler<ResponseMessage: Message>: ChannelInboundHandler {
   public typealias InboundIn = GRPCClientResponsePart<ResponseMessage>
   internal let logger: Logger
+  internal var stopwatch: Stopwatch?
 
   internal let initialMetadataPromise: EventLoopPromise<HPACKHeaders>
   internal let trailingMetadataPromise: EventLoopPromise<HPACKHeaders>
@@ -77,6 +78,15 @@ internal class GRPCClientResponseChannelHandler<ResponseMessage: Message>: Chann
     self.statusPromise.succeed(status)
     self.timeoutTask?.cancel()
     self.context = nil
+
+    if let stopwatch = self.stopwatch {
+      let millis = stopwatch.elapsedMillis()
+      self.logger.info("rpc call finished", metadata: [
+        "duration_ms": "\(millis)",
+        "status_code": "\(status.code.rawValue)"
+      ])
+      self.stopwatch = nil
+    }
   }
 
   /// Observe the given error.
@@ -102,6 +112,7 @@ internal class GRPCClientResponseChannelHandler<ResponseMessage: Message>: Chann
   public func handlerAdded(context: ChannelHandlerContext) {
     // We need to hold the context in case we timeout and need to close the pipeline.
     self.context = context
+    self.stopwatch = .start()
   }
 
   /// Reads inbound data.
@@ -186,10 +197,7 @@ final class GRPCClientUnaryResponseChannelHandler<ResponseMessage: Message>: GRP
       statusPromise: statusPromise,
       errorDelegate: errorDelegate,
       timeout: timeout,
-      logger: logger.addingMetadata(
-        key: MetadataKey.channelHandler,
-        value: "GRPCClientUnaryResponseChannelHandler"
-      )
+      logger: logger
     )
   }
 
@@ -241,10 +249,7 @@ final class GRPCClientStreamingResponseChannelHandler<ResponseMessage: Message>:
       statusPromise: statusPromise,
       errorDelegate: errorDelegate,
       timeout: timeout,
-      logger: logger.addingMetadata(
-        key: MetadataKey.channelHandler,
-        value: "GRPCClientStreamingResponseChannelHandler"
-      )
+      logger: logger
     )
   }
 

Sources/GRPC/GRPCClientStateMachine.swift

@@ -159,35 +159,22 @@ struct GRPCClientStateMachine<Request: Message, Response: Message> {
     }
   }
 
-  private let logger: Logger
-
   /// Creates a state machine representing a gRPC client's request and response stream state.
   ///
   /// - Parameter requestArity: The expected number of messages on the request stream.
   /// - Parameter responseArity: The expected number of messages on the response stream.
-  /// - Parameter logger: Logger.
-  init(
-    requestArity: MessageArity,
-    responseArity: MessageArity,
-    logger: Logger
-  ) {
+  init(requestArity: MessageArity, responseArity: MessageArity) {
     self.state = .clientIdleServerIdle(
       pendingWriteState: .init(arity: requestArity, compression: .none, contentType: .protobuf),
       readArity: responseArity
     )
-    self.logger = logger
   }
 
   /// Creates a state machine representing a gRPC client's request and response stream state.
   ///
   /// - Parameter state: The initial state of the state machine.
-  /// - Parameter logger: Logger.
-  init(
-    state: State,
-    logger: Logger
-  ) {
+  init(state: State) {
     self.state = state
-    self.logger = logger
   }
 
   /// Initiates an RPC.
@@ -277,7 +264,7 @@ struct GRPCClientStateMachine<Request: Message, Response: Message> {
   mutating func receiveResponseHeaders(
     _ headers: HPACKHeaders
   ) -> Result<Void, ReceiveResponseHeadError> {
-    return self.state.receiveResponseHeaders(headers, logger: self.logger)
+    return self.state.receiveResponseHeaders(headers)
   }
 
   /// Read a response buffer from the server and return any decoded messages.
@@ -424,19 +411,18 @@ extension GRPCClientStateMachine.State {
 
   /// See `GRPCClientStateMachine.receiveResponseHeaders(_:)`.
   mutating func receiveResponseHeaders(
-    _ headers: HPACKHeaders,
-    logger: Logger
+    _ headers: HPACKHeaders
   ) -> Result<Void, ReceiveResponseHeadError> {
     let result: Result<Void, ReceiveResponseHeadError>
 
     switch self {
     case let .clientActiveServerIdle(writeState, readArity):
-      result = self.parseResponseHeaders(headers, arity: readArity, logger: logger).map { readState in
+      result = self.parseResponseHeaders(headers, arity: readArity).map { readState in
         self = .clientActiveServerActive(writeState: writeState, readState: readState)
       }
 
     case let .clientClosedServerIdle(readArity):
-      result = self.parseResponseHeaders(headers, arity: readArity, logger: logger).map { readState in
+      result = self.parseResponseHeaders(headers, arity: readArity).map { readState in
         self = .clientClosedServerActive(readState: readState)
       }
 
@@ -550,8 +536,7 @@ extension GRPCClientStateMachine.State {
   /// - Parameter headers: The headers to parse.
   private func parseResponseHeaders(
     _ headers: HPACKHeaders,
-    arity: MessageArity,
-    logger: Logger
+    arity: MessageArity
   ) -> Result<ReadState, ReceiveResponseHeadError> {
     // From: https://github.com/grpc/grpc/blob/master/doc/PROTOCOL-HTTP2.md#responses
     //
@@ -583,12 +568,7 @@ extension GRPCClientStateMachine.State {
       return .failure(.unsupportedMessageEncoding(compression.rawValue))
     }
 
-    let reader = LengthPrefixedMessageReader(
-      mode: .client,
-      compressionMechanism: compression,
-      logger: logger
-    )
-
+    let reader = LengthPrefixedMessageReader(mode: .client, compressionMechanism: compression)
     return .success(.reading(arity, reader))
   }
 

Sources/GRPC/HTTP1ToRawGRPCServerCodec.swift

@@ -45,17 +45,13 @@ public enum RawGRPCServerResponsePart {
 /// The translation from HTTP2 to HTTP1 is done by `HTTP2ToHTTP1ServerCodec`.
 public final class HTTP1ToRawGRPCServerCodec {
   public init(logger: Logger) {
-    self.logger = logger.addingMetadata(key: MetadataKey.channelHandler, value: "HTTP1ToRawGRPCServerCodec")
+    self.logger = logger
 
     var accessLog = Logger(subsystem: .serverAccess)
     accessLog[metadataKey: MetadataKey.requestID] = logger[metadataKey: MetadataKey.requestID]
     self.accessLog = accessLog
 
-    self.messageReader = LengthPrefixedMessageReader(
-      mode: .server,
-      compressionMechanism: .none,
-      logger: logger
-    )
+    self.messageReader = LengthPrefixedMessageReader(mode: .server, compressionMechanism: .none)
   }
 
   // 1-byte for compression flag, 4-bytes for message length.
@@ -86,13 +82,13 @@ public final class HTTP1ToRawGRPCServerCodec {
   var inboundState = InboundState.expectingHeaders {
     willSet {
       guard newValue != self.inboundState else { return }
-      self.logger.info("inbound state changed from \(self.inboundState) to \(newValue)")
+      self.logger.debug("inbound state changed from \(self.inboundState) to \(newValue)")
     }
   }
   var outboundState = OutboundState.expectingHeaders {
     willSet {
       guard newValue != self.outboundState else { return }
-      self.logger.info("outbound state changed from \(self.outboundState) to \(newValue)")
+      self.logger.debug("outbound state changed from \(self.outboundState) to \(newValue)")
     }
   }
 

Sources/GRPC/HTTPProtocolSwitcher.swift

@@ -24,10 +24,7 @@ import Logging
 public class HTTPProtocolSwitcher {
   private let handlersInitializer: ((Channel) -> EventLoopFuture<Void>)
   private let errorDelegate: ServerErrorDelegate?
-  private let logger = Logger(
-    subsystem: .serverChannelCall,
-    metadata: [MetadataKey.channelHandler: "HTTPProtocolSwitcher"]
-  )
+  private let logger = Logger(subsystem: .serverChannelCall)
 
   // We could receive additional data after the initial data and before configuring
   // the pipeline; buffer it and fire it down the pipeline once it is configured.
@@ -39,7 +36,7 @@ public class HTTPProtocolSwitcher {
 
   private var state: State = .notConfigured {
     willSet {
-      self.logger.info("state changed from '\(self.state)' to '\(newValue)'")
+      self.logger.debug("state changed from '\(self.state)' to '\(newValue)'")
     }
   }
   private var bufferedData: [NIOAny] = []
@@ -75,9 +72,9 @@ extension HTTPProtocolSwitcher: ChannelInboundHandler, RemovableChannelHandler {
   public func channelRead(context: ChannelHandlerContext, data: NIOAny) {
     switch self.state {
     case .notConfigured:
-      self.logger.info("determining http protocol version")
+      self.logger.debug("determining http protocol version")
       self.state = .configuring
-      self.logger.info("buffering data \(data)")
+      self.logger.debug("buffering data \(data)")
       self.bufferedData.append(data)
 
       // Detect the HTTP protocol version for the incoming request, or error out if it
@@ -106,7 +103,7 @@ extension HTTPProtocolSwitcher: ChannelInboundHandler, RemovableChannelHandler {
         return
       }
 
-      self.logger.info("determined http version", metadata: ["http_version": "\(version)"])
+      self.logger.debug("determined http version", metadata: ["http_version": "\(version)"])
 
       // Once configured remove ourself from the pipeline, or handle the error.
       let pipelineConfigured: EventLoopPromise<Void> = context.eventLoop.makePromise()
@@ -144,7 +141,7 @@ extension HTTPProtocolSwitcher: ChannelInboundHandler, RemovableChannelHandler {
       }
 
     case .configuring:
-      self.logger.info("buffering data \(data)")
+      self.logger.debug("buffering data \(data)")
       self.bufferedData.append(data)
 
     case .configured:
@@ -154,7 +151,7 @@ extension HTTPProtocolSwitcher: ChannelInboundHandler, RemovableChannelHandler {
   }
 
   public func removeHandler(context: ChannelHandlerContext, removalToken: ChannelHandlerContext.RemovalToken) {
-    self.logger.info("unbuffering data")
+    self.logger.debug("unbuffering data")
     self.bufferedData.forEach {
       context.fireChannelRead($0)
     }

Sources/GRPC/LengthPrefixedMessageReader.swift

@@ -32,15 +32,13 @@ import Logging
 /// [gRPC Protocol](https://github.com/grpc/grpc/blob/master/doc/PROTOCOL-HTTP2.md)
 public class LengthPrefixedMessageReader {
   public typealias Mode = GRPCError.Origin
-  let logger: Logger
 
   /// The mechanism that messages will be compressed with.
   public var compressionMechanism: CompressionMechanism
 
-  public init(mode: Mode, compressionMechanism: CompressionMechanism, logger: Logger) {
+  public init(mode: Mode, compressionMechanism: CompressionMechanism) {
     self.mode = mode
     self.compressionMechanism = compressionMechanism
-    self.logger = logger
   }
 
   /// The result of trying to parse a message with the bytes we currently have.
@@ -63,11 +61,7 @@ public class LengthPrefixedMessageReader {
 
   private let mode: Mode
   private var buffer: ByteBuffer!
-  private var state: ParseState = .expectingCompressedFlag {
-    didSet {
-      self.logger.trace("parse state changed from \(oldValue) to \(self.state)")
-    }
-  }
+  private var state: ParseState = .expectingCompressedFlag
 
   /// Returns the number of unprocessed bytes.
   internal var unprocessedBytes: Int {
@@ -89,15 +83,12 @@ public class LengthPrefixedMessageReader {
     guard buffer.readableBytes > 0 else {
       return
     }
-    self.logger.trace("appending \(buffer.readableBytes) bytes to buffer")
 
     if self.buffer == nil {
-      self.logger.trace("creating new buffer from slice")
       self.buffer = buffer.slice()
       // mark the bytes as "read"
       buffer.moveReaderIndex(forwardBy: buffer.readableBytes)
     } else {
-      self.logger.trace("copying bytes into existing buffer")
       self.buffer.writeBuffer(&buffer)
     }
   }
@@ -117,7 +108,6 @@ public class LengthPrefixedMessageReader {
       return try nextMessage()
 
     case .message(let message):
-      self.logger.trace("read length-prefixed message")
       self.nilBufferIfPossible()
       return message
     }
@@ -128,42 +118,34 @@ public class LengthPrefixedMessageReader {
   /// This allows the next call to `append` to avoid writing the contents of the appended buffer.
   private func nilBufferIfPossible() {
     if self.buffer?.readableBytes == 0 {
-      self.logger.trace("no readable bytes; nilling-out buffer")
       self.buffer = nil
     }
   }
 
   private func processNextState() throws -> ParseResult {
     guard self.buffer != nil else {
-      self.logger.trace("no buffer to read from")
       return .needMoreData
     }
 
     switch self.state {
     case .expectingCompressedFlag:
       guard let compressionFlag: Int8 = self.buffer.readInteger() else {
-        self.logger.trace("1 more byte needed to read compression flag")
         return .needMoreData
       }
-      self.logger.trace("read 1 byte compression flag: \(compressionFlag)")
       try self.handleCompressionFlag(enabled: compressionFlag != 0)
       self.state = .expectingMessageLength
 
     case .expectingMessageLength:
       guard let messageLength: UInt32 = self.buffer.readInteger() else {
-        self.logger.trace("\(4 - buffer.readableBytes) more bytes needed to read message length")
         return .needMoreData
       }
-      self.logger.trace("read 4 byte message length: \(messageLength)")
       self.state = .expectingMessage(messageLength)
 
     case .expectingMessage(let length):
       let signedLength: Int = numericCast(length)
       guard let message = self.buffer.readSlice(length: signedLength) else {
-        self.logger.trace("\(signedLength - buffer.readableBytes) more bytes needed to read message")
         return .needMoreData
       }
-      self.logger.trace("read \(message.readableBytes) byte message")
       self.state = .expectingCompressedFlag
       return .message(message)
     }
@@ -173,18 +155,14 @@ public class LengthPrefixedMessageReader {
 
   private func handleCompressionFlag(enabled flagEnabled: Bool) throws {
     guard flagEnabled else {
-      self.logger.trace("compression is not enabled for this message")
       return
     }
-    self.logger.trace("compression is enabled for this message")
 
     guard self.compressionMechanism.requiresFlag else {
-      self.logger.error("compression flag was set but '\(self.compressionMechanism)' does not require it")
       throw GRPCError.common(.unexpectedCompression, origin: mode)
     }
 
     guard self.compressionMechanism.supported else {
-      self.logger.error("compression mechanism '\(self.compressionMechanism)' is not supported")
       throw GRPCError.common(.unsupportedCompressionMechanism(compressionMechanism.rawValue), origin: mode)
     }
   }

Sources/GRPC/PlatformSupport.swift

@@ -159,7 +159,7 @@ public enum PlatformSupport {
   ///
   /// - Parameter group: The `EventLoopGroup` to use.
   public static func makeClientBootstrap(group: EventLoopGroup) -> ClientBootstrapProtocol {
-    logger.info("making client bootstrap with event loop group of type \(type(of: group))")
+    logger.debug("making client bootstrap with event loop group of type \(type(of: group))")
     #if canImport(Network)
     if #available(OSX 10.14, iOS 12.0, tvOS 12.0, watchOS 6.0, *) {
       if let tsGroup = group as? NIOTSEventLoopGroup {
@@ -183,7 +183,7 @@ public enum PlatformSupport {
   ///
   /// - Parameter group: The `EventLoopGroup` to use.
   public static func makeServerBootstrap(group: EventLoopGroup) -> ServerBootstrapProtocol {
-    logger.info("making server bootstrap with event loop group of type \(type(of: group))")
+    logger.debug("making server bootstrap with event loop group of type \(type(of: group))")
     #if canImport(Network)
     if #available(OSX 10.14, iOS 12.0, tvOS 12.0, watchOS 6.0, *) {
       if let tsGroup = group as? NIOTSEventLoopGroup {

Sources/GRPC/SettingsObservingHandler.swift

@@ -36,7 +36,7 @@ class InitialSettingsObservingHandler: ChannelInboundHandler, RemovableChannelHa
     let frame = self.unwrapInboundIn(data)
 
     if frame.streamID == .rootStream, case .settings(.settings) = frame.payload {
-      self.logger.info("observed initial settings frame on the root stream")
+      self.logger.debug("observed initial settings frame on the root stream")
       self.connectivityStateMonitor.state = .ready
 
       // We're no longer needed at this point, remove ourselves from the pipeline.

Sources/GRPC/TLSVerificationHandler.swift

@@ -45,7 +45,7 @@ public class TLSVerificationHandler: ChannelInboundHandler, RemovableChannelHand
 
   /// A future which is fulfilled when the state of the TLS handshake is known. If the handshake
   /// was successful and the negotiated application protocol is valid then the future is succeeded.
-  /// If an error occured or the application protocol is not valid then the future will have been
+  /// If an error occurred or the application protocol is not valid then the future will have been
   /// failed.
   ///
   /// - Important: The promise associated with this future is created in `handlerAdded(context:)`,

Tests/GRPCTests/GRPCClientStateMachineTests.swift

@@ -31,10 +31,7 @@ class GRPCClientStateMachineTests: GRPCTestCase {
   var allocator = ByteBufferAllocator()
 
   func makeStateMachine(_ state: StateMachine.State) -> StateMachine {
-    return StateMachine(
-      state: state,
-      logger: Logger(label: "io.grpc.testing")
-    )
+    return StateMachine(state: state)
   }
 
   /// Writes a message into a new `ByteBuffer` (with length-prefixing).
@@ -934,8 +931,7 @@ extension ReadState {
   static func one() -> ReadState {
     let reader = LengthPrefixedMessageReader(
       mode: .client,
-      compressionMechanism: .none,
-      logger: Logger(label: "io.grpc.reader")
+      compressionMechanism: .none
     )
     return .reading(.one, reader)
   }
@@ -943,8 +939,7 @@ extension ReadState {
   static func many() -> ReadState {
     let reader = LengthPrefixedMessageReader(
       mode: .client,
-      compressionMechanism: .none,
-      logger: Logger(label: "io.grpc.reader")
+      compressionMechanism: .none
     )
     return .reading(.many, reader)
   }

Tests/GRPCTests/LengthPrefixedMessageReaderTests.swift

@@ -24,11 +24,7 @@ class LengthPrefixedMessageReaderTests: GRPCTestCase {
 
   override func setUp() {
     super.setUp()
-    self.reader = LengthPrefixedMessageReader(
-      mode: .client,
-      compressionMechanism: .none,
-      logger: Logger(label: "io.grpc.testing")
-    )
+    self.reader = LengthPrefixedMessageReader(mode: .client, compressionMechanism: .none)
   }
 
   var allocator = ByteBufferAllocator()