Allow loggers to be passed in (#902)

* Allow loggers to be passed in

Motivation:

The community recently discussed how logging should be done for the
`AsyncHTTPClient` project. One of the outcomes was that frameworks
should not log unless they are explicitly passed a logger. This allows
applications to decide whether they care about logging for that
component and have more control over the level at which that component
logs at.

Modifications:

- Client allows for loggers in two places: one for background activity
  (connectivity state management and so on) and another for RPCs
- Server allows a single logger to be specificed
- By default all loggers are no-op loggers
- Added 'none' option for 'CallOptions.RequestIDProvider' for cases
  where the request ID is already present on the logger

Result:

- gRPC does not log by default
- Note: this includes tests, this will be addressed in a separate PR to
  keep PR size down

Author: glbrntt

Package.resolved

@@ -6,8 +6,8 @@
         "repositoryURL": "https://github.com/apple/swift-log.git",
         "state": {
           "branch": null,
-          "revision": "74d7b91ceebc85daf387ebb206003f78813f71aa",
-          "version": "1.2.0"
+          "revision": "173f567a2dfec11d74588eea82cecea555bdc0bc",
+          "version": "1.4.0"
         }
       },
       {

Package.swift

@@ -39,7 +39,7 @@ let package = Package(
     .package(url: "https://github.com/apple/swift-protobuf.git", from: "1.9.0"),
 
     // Logging API.
-    .package(url: "https://github.com/apple/swift-log.git", from: "1.2.0"),
+    .package(url: "https://github.com/apple/swift-log.git", from: "1.4.0"),
   ],
   targets: [
     // The main GRPC module.

Sources/GRPC/ClientCalls/ClientCallTransport.swift

@@ -169,7 +169,11 @@ internal class ChannelTransport<Request, Response> {
         switch result {
         case .success(let mux):
           mux.createStreamChannel(promise: streamPromise) { stream, streamID in
-            stream.pipeline.addHandlers([
+            var logger = logger
+            logger[metadataKey: MetadataKey.streamID] = "\(streamID)"
+            logger.trace("created http/2 stream")
+
+            return stream.pipeline.addHandlers([
               _GRPCClientChannelHandler(streamID: streamID, callType: callType, logger: logger),
               GRPCClientCodecHandler(serializer: serializer, deserializer: deserializer),
               GRPCClientCallHandler(call: call)

Sources/GRPC/ClientConnection.swift

@@ -118,7 +118,7 @@ public class ClientConnection {
     self.authority = configuration.target.host
     self.connectionManager = ConnectionManager(
       configuration: configuration,
-      logger: Logger(subsystem: .clientChannel)
+      logger: configuration.backgroundActivityLogger
     )
   }
 
@@ -127,19 +127,28 @@ public class ClientConnection {
     return self.connectionManager.shutdown()
   }
 
-  private func loggerWithRequestID(_ requestID: String) -> Logger {
-    var logger = self.connectionManager.logger
-    logger[metadataKey: MetadataKey.requestID] = "\(requestID)"
-    return logger
+  /// Extracts a logger and request ID from the call options and returns them. The logger will
+  /// be populated with the request ID (if applicable) and any metadata from the connection manager.
+  private func populatedLoggerAndRequestID(from callOptions: CallOptions) -> (Logger, String?) {
+    var logger = callOptions.logger
+    self.connectionManager.appendMetadata(to: &logger)
+
+    // Attach the request ID.
+    let requestID = callOptions.requestIDProvider.requestID()
+    if let requestID = requestID {
+      logger[metadataKey: MetadataKey.requestID] = "\(requestID)"
+    }
+
+    return (logger, requestID)
   }
 
-  private func makeRequestHead(path: String, options: CallOptions, requestID: String) -> _GRPCRequestHead {
+  private func makeRequestHead(path: String, options: CallOptions, requestID: String?) -> _GRPCRequestHead {
     return _GRPCRequestHead(
       scheme: self.scheme,
       path: path,
       host: self.authority,
-      requestID: requestID,
-      options: options
+      options: options,
+      requestID: requestID
     )
   }
 }
@@ -154,8 +163,7 @@ extension ClientConnection: GRPCChannel {
     request: Serializer.Input,
     callOptions: CallOptions
   ) -> UnaryCall<Serializer.Input, Deserializer.Output> {
-    let requestID = callOptions.requestIDProvider.requestID()
-    let logger = self.loggerWithRequestID(requestID)
+    let (logger, requestID) = self.populatedLoggerAndRequestID(from: callOptions)
     logger.debug("starting rpc", metadata: ["path": "\(path)"])
 
     let call = UnaryCall<Serializer.Input, Deserializer.Output>.makeOnHTTP2Stream(
@@ -212,8 +220,7 @@ extension ClientConnection {
     path: String,
     callOptions: CallOptions
   ) -> ClientStreamingCall<Serializer.Input, Deserializer.Output> {
-    let requestID = callOptions.requestIDProvider.requestID()
-    let logger = self.loggerWithRequestID(requestID)
+    let (logger, requestID) = self.populatedLoggerAndRequestID(from: callOptions)
     logger.debug("starting rpc", metadata: ["path": "\(path)"])
 
     let call = ClientStreamingCall<Serializer.Input, Deserializer.Output>.makeOnHTTP2Stream(
@@ -268,8 +275,7 @@ extension ClientConnection {
     callOptions: CallOptions,
     handler: @escaping (Deserializer.Output) -> Void
   ) -> ServerStreamingCall<Serializer.Input, Deserializer.Output> {
-    let requestID = callOptions.requestIDProvider.requestID()
-    let logger = self.loggerWithRequestID(requestID)
+    let (logger, requestID) = self.populatedLoggerAndRequestID(from: callOptions)
     logger.debug("starting rpc", metadata: ["path": "\(path)"])
 
     let call = ServerStreamingCall<Serializer.Input, Deserializer.Output>.makeOnHTTP2Stream(
@@ -332,8 +338,7 @@ extension ClientConnection {
     callOptions: CallOptions,
     handler: @escaping (Deserializer.Output) -> Void
   ) -> BidirectionalStreamingCall<Serializer.Input, Deserializer.Output> {
-    let requestID = callOptions.requestIDProvider.requestID()
-    let logger = self.loggerWithRequestID(requestID)
+    let (logger, requestID) = self.populatedLoggerAndRequestID(from: callOptions)
     logger.debug("starting rpc", metadata: ["path": "\(path)"])
 
     let call = BidirectionalStreamingCall<Serializer.Input, Deserializer.Output>.makeOnHTTP2Stream(
@@ -507,6 +512,12 @@ extension ClientConnection {
       return self.tls == nil ? .http : .https
     }
 
+    /// A logger for background information (such as connectivity state). A separate logger for
+    /// requests may be provided in the `CallOptions`.
+    ///
+    /// Defaults to a no-op logger.
+    public var backgroundActivityLogger: Logger
+
     /// Create a `Configuration` with some pre-defined defaults. Prefer using
     /// `ClientConnection.secure(group:)` to build a connection secured with TLS or
     /// `ClientConnection.insecure(group:)` to build a plaintext connection.
@@ -525,6 +536,8 @@ extension ClientConnection {
     /// - Parameter callStartBehavior: The behavior used to determine when a call should start in
     ///     relation to its underlying connection. Defaults to `waitsForConnectivity`.
     /// - Parameter httpTargetWindowSize: The HTTP/2 flow control target window size.
+    /// - Parameter logger: A logger for background information (such as connectivity state).
+    ///     Defaults to a no-op logger.
     public init(
       target: ConnectionTarget,
       eventLoopGroup: EventLoopGroup,
@@ -536,7 +549,8 @@ extension ClientConnection {
       connectionKeepalive: ClientConnectionKeepalive = ClientConnectionKeepalive(),
       connectionIdleTimeout: TimeAmount = .minutes(5),
       callStartBehavior: CallStartBehavior = .waitsForConnectivity,
-      httpTargetWindowSize: Int = 65535
+      httpTargetWindowSize: Int = 65535,
+      backgroundActivityLogger: Logger = Logger(label: "io.grpc", factory: { _ in SwiftLogNoOpLogHandler() })
     ) {
       self.target = target
       self.eventLoopGroup = eventLoopGroup
@@ -549,6 +563,7 @@ extension ClientConnection {
       self.connectionIdleTimeout = connectionIdleTimeout
       self.callStartBehavior = callStartBehavior
       self.httpTargetWindowSize = httpTargetWindowSize
+      self.backgroundActivityLogger = backgroundActivityLogger
     }
   }
 }

Sources/GRPC/ClientOptions.swift

@@ -14,6 +14,7 @@
  * limitations under the License.
  */
 import struct Foundation.UUID
+import Logging
 import NIOHTTP1
 import NIOHTTP2
 import NIOHPACK
@@ -60,24 +61,33 @@ public struct CallOptions {
   /// messages associated with the call.
   public var requestIDHeader: String?
 
+  /// A logger used for the call. Defaults to a no-op logger.
+  ///
+  /// If a `requestIDProvider` exists then a request ID will automatically attached to the logger's
+  /// metadata using the 'grpc-request-id' key.
+  public var logger: Logger
+
   public init(
     customMetadata: HPACKHeaders = HPACKHeaders(),
     timeLimit: TimeLimit = .none,
     messageEncoding: ClientMessageEncoding = .disabled,
     requestIDProvider: RequestIDProvider = .autogenerated,
     requestIDHeader: String? = nil,
-    cacheable: Bool = false
+    cacheable: Bool = false,
+    logger: Logger = Logger(label: "io.grpc", factory: { _ in SwiftLogNoOpLogHandler() })
   ) {
     self.customMetadata = customMetadata
     self.messageEncoding = messageEncoding
     self.requestIDProvider = requestIDProvider
     self.requestIDHeader = requestIDHeader
     self.cacheable = false
     self.timeLimit = timeLimit
+    self.logger = logger
   }
 
   public struct RequestIDProvider {
     private enum RequestIDSource {
+      case none
       case `static`(String)
       case generated(() -> String)
     }
@@ -87,15 +97,20 @@ public struct CallOptions {
       self.source = source
     }
 
-    internal func requestID() -> String {
+    internal func requestID() -> String? {
       switch self.source {
+      case .none:
+        return nil
       case .static(let requestID):
         return requestID
       case .generated(let generator):
         return generator()
       }
     }
 
+    /// No request IDs are generated.
+    public static let none = RequestIDProvider(.none)
+
     /// Generate a new request ID for each RPC.
     public static let autogenerated = RequestIDProvider(.generated({ UUID().uuidString }))
 

Sources/GRPC/ConnectionManager.swift

@@ -149,8 +149,10 @@ internal class ConnectionManager {
         self.monitor.updateState(to: .idle, logger: self.logger)
 
         // Create a new id; it'll be used for the *next* channel we create.
-        self.channelNumber &+= 1
-        self.logger[metadataKey: MetadataKey.connectionID] = "\(self.connectionId)/\(self.channelNumber)"
+        self.channelNumberLock.withLockVoid {
+          self.channelNumber &+= 1
+        }
+        self.logger[metadataKey: MetadataKey.connectionID] = "\(self.connectionIDAndNumber)"
 
       case .connecting:
         self.monitor.updateState(to: .connecting, logger: self.logger)
@@ -175,8 +177,19 @@ internal class ConnectionManager {
   internal let monitor: ConnectivityStateMonitor
   internal var logger: Logger
 
-  private let connectionId: String
+  private let connectionID: String
   private var channelNumber: UInt64
+  private var channelNumberLock = Lock()
+
+  private var connectionIDAndNumber: String {
+    return self.channelNumberLock.withLock {
+      return "\(self.connectionID)/\(self.channelNumber)"
+    }
+  }
+
+  internal func appendMetadata(to logger: inout Logger) {
+    logger[metadataKey: MetadataKey.connectionID] = "\(self.connectionIDAndNumber)"
+  }
 
   // Only used for testing.
   private var channelProvider: (() -> EventLoopFuture<Channel>)?
@@ -205,9 +218,9 @@ internal class ConnectionManager {
   ) {
     // Setup the logger.
     var logger = logger
-    let connectionId = UUID().uuidString
+    let connectionID = UUID().uuidString
     let channelNumber: UInt64 = 0
-    logger[metadataKey: MetadataKey.connectionID] = "\(connectionId)/\(channelNumber)"
+    logger[metadataKey: MetadataKey.connectionID] = "\(connectionID)/\(channelNumber)"
 
     let eventLoop = configuration.eventLoopGroup.next()
     self.eventLoop = eventLoop
@@ -219,7 +232,7 @@ internal class ConnectionManager {
 
     self.channelProvider = channelProvider
 
-    self.connectionId = connectionId
+    self.connectionID = connectionID
     self.channelNumber = channelNumber
     self.logger = logger
   }

Sources/GRPC/FakeChannel.swift

@@ -33,7 +33,7 @@ public class FakeChannel: GRPCChannel {
   /// A logger.
   public let logger: Logger
 
-  public init(logger: Logger = Logger(label: "io.grpc.testing")) {
+  public init(logger: Logger = Logger(label: "io.grpc", factory: { _ in SwiftLogNoOpLogHandler() })) {
     self.responseStreams = [:]
     self.logger = logger
   }
@@ -217,8 +217,8 @@ extension FakeChannel {
       scheme: "http",
       path: path,
       host: "localhost",
-      requestID: callOptions.requestIDProvider.requestID(),
-      options: callOptions
+      options: callOptions,
+      requestID: nil
     )
   }
 }

Sources/GRPC/GRPCChannel/EmbeddedGRPCChannel.swift

@@ -36,10 +36,12 @@ class EmbeddedGRPCChannel: GRPCChannel {
     return self.embeddedChannel.eventLoop
   }
 
-  init(errorDelegate: ClientErrorDelegate? = nil) {
+  init(
+    logger: Logger = Logger(label: "io.grpc", factory: { _ in SwiftLogNoOpLogHandler() }),
+    errorDelegate: ClientErrorDelegate? = nil
+  ) {
     let embeddedChannel = EmbeddedChannel()
     self.embeddedChannel = embeddedChannel
-    let logger = Logger(subsystem: .clientChannel)
     self.logger = logger
     self.multiplexer = embeddedChannel.configureGRPCClient(
       errorDelegate: errorDelegate,
@@ -57,8 +59,8 @@ class EmbeddedGRPCChannel: GRPCChannel {
       scheme: self.scheme,
       path: path,
       host: self.authority,
-      requestID: options.requestIDProvider.requestID(),
-      options: options
+      options: options,
+      requestID: nil
     )
   }
 

Sources/GRPC/GRPCChannel/GRPCChannelBuilder.swift

@@ -14,6 +14,7 @@
  * limitations under the License.
  */
 import Dispatch
+import Logging
 import NIO
 import NIOSSL
 
@@ -42,6 +43,7 @@ extension ClientConnection {
     private var connectionIdleTimeout: TimeAmount = .minutes(5)
     private var callStartBehavior: CallStartBehavior = .waitsForConnectivity
     private var httpTargetWindowSize: Int = 65535
+    private var logger: Logger = Logger(label: "io.grpc", factory: { _ in SwiftLogNoOpLogHandler() })
 
     fileprivate init(group: EventLoopGroup) {
       self.group = group
@@ -59,7 +61,8 @@ extension ClientConnection {
         connectionKeepalive: self.connectionKeepalive,
         connectionIdleTimeout: self.connectionIdleTimeout,
         callStartBehavior: self.callStartBehavior,
-        httpTargetWindowSize: self.httpTargetWindowSize
+        httpTargetWindowSize: self.httpTargetWindowSize,
+        backgroundActivityLogger: self.logger
       )
       return ClientConnection(configuration: configuration)
     }
@@ -249,6 +252,19 @@ extension ClientConnection.Builder {
   }
 }
 
+extension ClientConnection.Builder {
+  /// Sets a logger to be used for background activity such as connection state changes. Defaults
+  /// to a no-op logger if not explicitly set.
+  ///
+  /// Note that individual RPCs will use the logger from `CallOptions`, not the logger specified
+  /// here.
+  @discardableResult
+  public func withBackgroundActivityLogger(_ logger: Logger) -> Self {
+    self.logger = logger
+    return self
+  }
+}
+
 fileprivate extension Double {
   static func seconds(from amount: TimeAmount) -> Double {
     return Double(amount.nanoseconds) / 1_000_000_000

Sources/GRPC/GRPCServerRequestRoutingHandler.swift

@@ -221,13 +221,9 @@ extension GRPCServerRequestRoutingHandler: ChannelInboundHandler, RemovableChann
     self.logger.debug("making call handler", metadata: ["path": "\(requestHead.uri)"])
     let uriComponents = requestHead.uri.components(separatedBy: "/")
 
-    var logger = self.logger
-    // Unset the channel handler: it shouldn't be used for downstream handlers.
-    logger[metadataKey: MetadataKey.channelHandler] = nil
-
     let context = CallHandlerContext(
       errorDelegate: self.errorDelegate,
-      logger: logger,
+      logger: self.logger,
       encoding: self.encoding
     )