From 28ff06b68a1cf8a36105d52d5897db7110ab292b Mon Sep 17 00:00:00 2001 From: George Barnett Date: Mon, 20 Jul 2020 14:01:57 +0100 Subject: [PATCH 1/3] 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 --- Package.resolved | 4 +- Package.swift | 2 +- .../ClientCalls/ClientCallTransport.swift | 6 ++- Sources/GRPC/ClientConnection.swift | 49 ++++++++++++------- Sources/GRPC/ClientOptions.swift | 23 +++++++-- Sources/GRPC/ConnectionManager.swift | 25 +++++++--- Sources/GRPC/FakeChannel.swift | 6 +-- .../GRPCChannel/EmbeddedGRPCChannel.swift | 10 ++-- .../GRPC/GRPCChannel/GRPCChannelBuilder.swift | 18 ++++++- .../GRPCServerRequestRoutingHandler.swift | 6 +-- Sources/GRPC/HTTP1ToGRPCServerCodec.swift | 9 +--- Sources/GRPC/HTTPProtocolSwitcher.swift | 35 ++++++------- Sources/GRPC/Logger.swift | 39 +-------------- Sources/GRPC/LoggingServerErrorDelegate.swift | 8 +-- Sources/GRPC/PlatformSupport.swift | 43 ++++++++-------- Sources/GRPC/Server.swift | 22 ++++++--- Sources/GRPC/ServerBuilder.swift | 16 +++++- Sources/GRPC/_GRPCClientChannelHandler.swift | 14 ++++-- .../InteroperabilityTestServer.swift | 8 ++- .../Benchmarks/EmbeddedClientThroughput.swift | 2 +- 20 files changed, 199 insertions(+), 146 deletions(-) diff --git a/Package.resolved b/Package.resolved index faeca1390..b42f1e6a4 100644 --- a/Package.resolved +++ b/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" } }, { diff --git a/Package.swift b/Package.swift index 4348e6a42..743aa2a68 100644 --- a/Package.swift +++ b/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. diff --git a/Sources/GRPC/ClientCalls/ClientCallTransport.swift b/Sources/GRPC/ClientCalls/ClientCallTransport.swift index 3808cbd99..43380ec3e 100644 --- a/Sources/GRPC/ClientCalls/ClientCallTransport.swift +++ b/Sources/GRPC/ClientCalls/ClientCallTransport.swift @@ -169,7 +169,11 @@ internal class ChannelTransport { 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) diff --git a/Sources/GRPC/ClientConnection.swift b/Sources/GRPC/ClientConnection.swift index ff7ebcd51..d784615a6 100644 --- a/Sources/GRPC/ClientConnection.swift +++ b/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 { - 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.makeOnHTTP2Stream( @@ -212,8 +220,7 @@ extension ClientConnection { path: String, callOptions: CallOptions ) -> ClientStreamingCall { - 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.makeOnHTTP2Stream( @@ -268,8 +275,7 @@ extension ClientConnection { callOptions: CallOptions, handler: @escaping (Deserializer.Output) -> Void ) -> ServerStreamingCall { - 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.makeOnHTTP2Stream( @@ -332,8 +338,7 @@ extension ClientConnection { callOptions: CallOptions, handler: @escaping (Deserializer.Output) -> Void ) -> BidirectionalStreamingCall { - 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.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 } } } diff --git a/Sources/GRPC/ClientOptions.swift b/Sources/GRPC/ClientOptions.swift index 451bea011..8c0398799 100644 --- a/Sources/GRPC/ClientOptions.swift +++ b/Sources/GRPC/ClientOptions.swift @@ -14,6 +14,7 @@ * limitations under the License. */ import struct Foundation.UUID +import Logging import NIOHTTP1 import NIOHTTP2 import NIOHPACK @@ -43,7 +44,7 @@ public struct CallOptions { /// Whether the call is cacheable. public var cacheable: Bool - /// How IDs should be provided for requests. Defaults to `.autogenerated`. + /// How IDs should be provided for requests. Defaults to `.none`. /// /// The request ID is used for logging and will be added to the headers of a call if /// `requestIDHeader` is specified. @@ -60,13 +61,20 @@ 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, + requestIDProvider: RequestIDProvider = .none, requestIDHeader: String? = nil, - cacheable: Bool = false + cacheable: Bool = false, + logger: Logger = Logger(label: "io.grpc", factory: { _ in SwiftLogNoOpLogHandler() }) ) { self.customMetadata = customMetadata self.messageEncoding = messageEncoding @@ -74,10 +82,12 @@ public struct CallOptions { 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,8 +97,10 @@ 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): @@ -96,6 +108,9 @@ public struct CallOptions { } } + /// 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 })) diff --git a/Sources/GRPC/ConnectionManager.swift b/Sources/GRPC/ConnectionManager.swift index 048d0d9ef..14d26e725 100644 --- a/Sources/GRPC/ConnectionManager.swift +++ b/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)? @@ -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 } diff --git a/Sources/GRPC/FakeChannel.swift b/Sources/GRPC/FakeChannel.swift index 6c81cf0fc..0aca37141 100644 --- a/Sources/GRPC/FakeChannel.swift +++ b/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 ) } } diff --git a/Sources/GRPC/GRPCChannel/EmbeddedGRPCChannel.swift b/Sources/GRPC/GRPCChannel/EmbeddedGRPCChannel.swift index 005996362..cf260a15f 100644 --- a/Sources/GRPC/GRPCChannel/EmbeddedGRPCChannel.swift +++ b/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 ) } diff --git a/Sources/GRPC/GRPCChannel/GRPCChannelBuilder.swift b/Sources/GRPC/GRPCChannel/GRPCChannelBuilder.swift index 1c6d39068..4f251e7f9 100644 --- a/Sources/GRPC/GRPCChannel/GRPCChannelBuilder.swift +++ b/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 diff --git a/Sources/GRPC/GRPCServerRequestRoutingHandler.swift b/Sources/GRPC/GRPCServerRequestRoutingHandler.swift index 1271282d6..ce9d3f757 100644 --- a/Sources/GRPC/GRPCServerRequestRoutingHandler.swift +++ b/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 ) diff --git a/Sources/GRPC/HTTP1ToGRPCServerCodec.swift b/Sources/GRPC/HTTP1ToGRPCServerCodec.swift index 8966b9117..f845a86a0 100644 --- a/Sources/GRPC/HTTP1ToGRPCServerCodec.swift +++ b/Sources/GRPC/HTTP1ToGRPCServerCodec.swift @@ -54,10 +54,6 @@ public final class HTTP1ToGRPCServerCodec { self.encoding = encoding self.encodingHeaderValidator = MessageEncodingHeaderValidator(encoding: encoding) self.logger = logger - - var accessLog = Logger(subsystem: .serverAccess) - accessLog[metadataKey: MetadataKey.requestID] = logger[metadataKey: MetadataKey.requestID] - self.accessLog = accessLog self.messageReader = LengthPrefixedMessageReader() self.messageWriter = LengthPrefixedMessageWriter() } @@ -70,7 +66,6 @@ public final class HTTP1ToGRPCServerCodec { private var responseEncodingHeader: String? = nil private let logger: Logger - private let accessLog: Logger private var stopwatch: Stopwatch? // The following buffers use force unwrapping explicitly. With optionals, developers @@ -157,7 +152,7 @@ extension HTTP1ToGRPCServerCodec: ChannelInboundHandler { } self.stopwatch = .start() - self.accessLog.debug("rpc call started", metadata: [ + self.logger.debug("rpc call started", metadata: [ "path": "\(requestHead.uri)", "method": "\(requestHead.method)", "version": "\(requestHead.version)" @@ -424,7 +419,7 @@ extension HTTP1ToGRPCServerCodec: ChannelOutboundHandler { self.stopwatch = nil let millis = stopwatch.elapsedMillis() - self.accessLog.debug("rpc call finished", metadata: [ + self.logger.debug("rpc call finished", metadata: [ "duration_ms": "\(millis)", "status_code": "\(status.code.rawValue)" ]) diff --git a/Sources/GRPC/HTTPProtocolSwitcher.swift b/Sources/GRPC/HTTPProtocolSwitcher.swift index bca93ba0a..be726bc07 100644 --- a/Sources/GRPC/HTTPProtocolSwitcher.swift +++ b/Sources/GRPC/HTTPProtocolSwitcher.swift @@ -22,9 +22,9 @@ import Logging /// Channel handler that creates different processing pipelines depending on whether /// the incoming request is HTTP 1 or 2. internal class HTTPProtocolSwitcher { - private let handlersInitializer: ((Channel) -> EventLoopFuture) + private let handlersInitializer: ((Channel, Logger) -> EventLoopFuture) private let errorDelegate: ServerErrorDelegate? - private let logger = Logger(subsystem: .serverChannelCall) + private let logger: Logger private let httpTargetWindowSize: Int private let keepAlive: ServerConnectionKeepalive private let idleTimeout: TimeAmount @@ -37,11 +37,7 @@ internal class HTTPProtocolSwitcher { case configured } - private var state: State = .notConfigured { - willSet { - self.logger.debug("state changed", metadata: ["old_state": "\(self.state)", "new_state": "\(newValue)"]) - } - } + private var state: State = .notConfigured private var bufferedData: [NIOAny] = [] init( @@ -49,12 +45,14 @@ internal class HTTPProtocolSwitcher { httpTargetWindowSize: Int = 65535, keepAlive: ServerConnectionKeepalive, idleTimeout: TimeAmount, - handlersInitializer: (@escaping (Channel) -> EventLoopFuture) + logger: Logger, + handlersInitializer: (@escaping (Channel, Logger) -> EventLoopFuture) ) { self.errorDelegate = errorDelegate self.httpTargetWindowSize = httpTargetWindowSize self.keepAlive = keepAlive self.idleTimeout = idleTimeout + self.logger = logger self.handlersInitializer = handlersInitializer } } @@ -140,7 +138,7 @@ extension HTTPProtocolSwitcher: ChannelInboundHandler, RemovableChannelHandler { // to support this. context.pipeline.configureHTTPServerPipeline(withErrorHandling: true) .flatMap { context.pipeline.addHandler(WebCORSHandler()) } - .flatMap { self.handlersInitializer(context.channel) } + .flatMap { self.handlersInitializer(context.channel, self.logger) } .cascade(to: pipelineConfigured) case .http2: @@ -148,15 +146,18 @@ extension HTTPProtocolSwitcher: ChannelInboundHandler, RemovableChannelHandler { mode: .server, targetWindowSize: httpTargetWindowSize ) { (streamChannel, streamID) in - streamChannel.pipeline.addHandler(HTTP2ToHTTP1ServerCodec(streamID: streamID, normalizeHTTPHeaders: true)) - .flatMap { self.handlersInitializer(streamChannel) } - }.flatMap { multiplexer in - // Add a keepalive and idle handlers between the two HTTP2 handlers. - let keepaliveHandler = GRPCServerKeepaliveHandler(configuration: self.keepAlive) - let idleHandler = GRPCIdleHandler(mode: .server, idleTimeout: self.idleTimeout) - return context.channel.pipeline.addHandlers([keepaliveHandler, idleHandler], position: .before(multiplexer)) + var logger = self.logger + logger[metadataKey: MetadataKey.streamID] = "\(streamID)" + return streamChannel.pipeline.addHandler(HTTP2ToHTTP1ServerCodec(streamID: streamID, normalizeHTTPHeaders: true)).flatMap { + self.handlersInitializer(streamChannel, logger) } - .cascade(to: pipelineConfigured) + }.flatMap { multiplexer in + // Add a keepalive and idle handlers between the two HTTP2 handlers. + let keepaliveHandler = GRPCServerKeepaliveHandler(configuration: self.keepAlive) + let idleHandler = GRPCIdleHandler(mode: .server, idleTimeout: self.idleTimeout) + return context.channel.pipeline.addHandlers([keepaliveHandler, idleHandler], position: .before(multiplexer)) + } + .cascade(to: pipelineConfigured) } case .configuring: diff --git a/Sources/GRPC/Logger.swift b/Sources/GRPC/Logger.swift index db50a2782..1815f1d13 100644 --- a/Sources/GRPC/Logger.swift +++ b/Sources/GRPC/Logger.swift @@ -13,49 +13,12 @@ * See the License for the specific language governing permissions and * limitations under the License. */ -import Foundation import Logging -extension Logger { - /// Create a logger and attach the given metadata. - init(label: String, metadata: Metadata) { - self.init(label: label) - for (key, value) in metadata { - self[metadataKey: key] = value - } - } - - /// Create a logger for the given subsystem and attach the given metadata. - init(subsystem: Subsystem, metadata: Metadata = [:]) { - self.init(label: "io.grpc.\(subsystem.rawValue)", metadata: metadata) - } - - /// Create a logger with a label in the format: `"io.grpc.\(suffix)"`. - init(labelSuffix suffix: String, metadata: Metadata = [:]) { - self.init(label: "io.grpc.\(suffix)", metadata: metadata) - } - - /// Creates a copy of the logger and sets metadata with the given key and value on the copy. - func addingMetadata(key: String, value: MetadataValue) -> Logger { - var newLogger = self - newLogger[metadataKey: key] = value - return newLogger - } - - /// Labels for logging subsystems. - enum Subsystem: String { - case clientChannel = "client_channel" - case serverChannelCall = "server_channel_call" - case serverAccess = "server_access" - case nio = "nio" - } -} - /// Keys for `Logger` metadata. enum MetadataKey { + static let streamID = "http2_stream_id" static let requestID = "request_id" - static let responseType = "response_type" - static let channelHandler = "channel_handler" static let connectionID = "connection_id" static let error = "error" } diff --git a/Sources/GRPC/LoggingServerErrorDelegate.swift b/Sources/GRPC/LoggingServerErrorDelegate.swift index 4d7ef48f7..8c55178ac 100644 --- a/Sources/GRPC/LoggingServerErrorDelegate.swift +++ b/Sources/GRPC/LoggingServerErrorDelegate.swift @@ -13,14 +13,14 @@ * See the License for the specific language governing permissions and * limitations under the License. */ -import Foundation import Logging public class LoggingServerErrorDelegate: ServerErrorDelegate { - public static let shared = LoggingServerErrorDelegate() - private let logger = Logger(labelSuffix: "ServerErrorDelegate") + private let logger: Logger - private init() {} + public init(logger: Logger) { + self.logger = logger + } public func observeLibraryError(_ error: Error) { self.logger.error("library error", metadata: [MetadataKey.error: "\(error)"]) diff --git a/Sources/GRPC/PlatformSupport.swift b/Sources/GRPC/PlatformSupport.swift index f1aa99141..cc00b281c 100644 --- a/Sources/GRPC/PlatformSupport.swift +++ b/Sources/GRPC/PlatformSupport.swift @@ -141,8 +141,6 @@ extension NIOTSListenerBootstrap: ServerBootstrapProtocol {} // MARK: - Bootstrap / EventLoopGroup helpers public enum PlatformSupport { - static let logger = Logger(subsystem: .nio) - /// Makes a new event loop group based on the network preference. /// /// If `.best` is chosen and `Network.framework` is available then `NIOTSEventLoopGroup` will @@ -155,23 +153,22 @@ public enum PlatformSupport { networkPreference: NetworkPreference = .best, logger: Logger? = nil ) -> EventLoopGroup { - let logger = logger ?? PlatformSupport.logger - logger.debug("making EventLoopGroup for \(networkPreference) network preference") + logger?.debug("making EventLoopGroup for \(networkPreference) network preference") switch networkPreference.implementation.wrapped { case .networkFramework: #if canImport(Network) guard #available(OSX 10.14, iOS 12.0, tvOS 12.0, watchOS 6.0, *) else { - logger.critical("Network.framework can be imported but is not supported on this platform") + logger?.critical("Network.framework can be imported but is not supported on this platform") // This is gated by the availability of `.networkFramework` so should never happen. fatalError(".networkFramework is being used on an unsupported platform") } - logger.debug("created NIOTSEventLoopGroup for \(networkPreference) preference") + logger?.debug("created NIOTSEventLoopGroup for \(networkPreference) preference") return NIOTSEventLoopGroup(loopCount: loopCount) #else fatalError(".networkFramework is being used on an unsupported platform") #endif case .posix: - logger.debug("created MultiThreadedEventLoopGroup for \(networkPreference) preference") + logger?.debug("created MultiThreadedEventLoopGroup for \(networkPreference) preference") return MultiThreadedEventLoopGroup(numberOfThreads: loopCount) } } @@ -182,22 +179,24 @@ public enum PlatformSupport { /// `NIOTSConnectionBootstrap`, otherwise it will be a `ClientBootstrap`. /// /// - Parameter group: The `EventLoopGroup` to use. - public static func makeClientBootstrap(group: EventLoopGroup, logger: Logger? = nil) -> ClientBootstrapProtocol { - let logger = logger ?? PlatformSupport.logger - logger.debug("making client bootstrap with event loop group of type \(type(of: group))") + public static func makeClientBootstrap( + group: EventLoopGroup, + logger: Logger? = nil + ) -> ClientBootstrapProtocol { + 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 { - logger.debug("Network.framework is available and the group is correctly typed, creating a NIOTSConnectionBootstrap") + logger?.debug("Network.framework is available and the group is correctly typed, creating a NIOTSConnectionBootstrap") return NIOTSConnectionBootstrap(group: tsGroup) } else if let qosEventLoop = group as? QoSEventLoop { - logger.debug("Network.framework is available and the group is correctly typed, creating a NIOTSConnectionBootstrap") + logger?.debug("Network.framework is available and the group is correctly typed, creating a NIOTSConnectionBootstrap") return NIOTSConnectionBootstrap(group: qosEventLoop) } - logger.debug("Network.framework is available but the group is not typed for NIOTS, falling back to ClientBootstrap") + logger?.debug("Network.framework is available but the group is not typed for NIOTS, falling back to ClientBootstrap") } #endif - logger.debug("creating a ClientBootstrap") + logger?.debug("creating a ClientBootstrap") return ClientBootstrap(group: group) } @@ -207,22 +206,24 @@ public enum PlatformSupport { /// `NIOTSListenerBootstrap`, otherwise it will be a `ServerBootstrap`. /// /// - Parameter group: The `EventLoopGroup` to use. - public static func makeServerBootstrap(group: EventLoopGroup, logger: Logger? = nil) -> ServerBootstrapProtocol { - let logger = logger ?? PlatformSupport.logger - logger.debug("making server bootstrap with event loop group of type \(type(of: group))") + public static func makeServerBootstrap( + group: EventLoopGroup, + logger: Logger? = nil + ) -> ServerBootstrapProtocol { + 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 { - logger.debug("Network.framework is available and the group is correctly typed, creating a NIOTSListenerBootstrap") + logger?.debug("Network.framework is available and the group is correctly typed, creating a NIOTSListenerBootstrap") return NIOTSListenerBootstrap(group: tsGroup) } else if let qosEventLoop = group as? QoSEventLoop { - logger.debug("Network.framework is available and the group is correctly typed, creating a NIOTSListenerBootstrap") + logger?.debug("Network.framework is available and the group is correctly typed, creating a NIOTSListenerBootstrap") return NIOTSListenerBootstrap(group: qosEventLoop) } - logger.debug("Network.framework is available but the group is not typed for NIOTS, falling back to ServerBootstrap") + logger?.debug("Network.framework is available but the group is not typed for NIOTS, falling back to ServerBootstrap") } #endif - logger.debug("creating a ServerBootstrap") + logger?.debug("creating a ServerBootstrap") return ServerBootstrap(group: group) } } diff --git a/Sources/GRPC/Server.swift b/Sources/GRPC/Server.swift index 32e547691..843923d07 100644 --- a/Sources/GRPC/Server.swift +++ b/Sources/GRPC/Server.swift @@ -103,9 +103,9 @@ public final class Server { errorDelegate: configuration.errorDelegate, httpTargetWindowSize: configuration.httpTargetWindowSize, keepAlive: configuration.connectionKeepalive, - idleTimeout: configuration.connectionIdleTimeout - ) { channel -> EventLoopFuture in - let logger = Logger(subsystem: .serverChannelCall, metadata: [MetadataKey.requestID: "\(UUID())"]) + idleTimeout: configuration.connectionIdleTimeout, + logger: configuration.logger + ) { (channel, logger) -> EventLoopFuture in let handler = GRPCServerRequestRoutingHandler( servicesByName: configuration.serviceProvidersByName, encoding: configuration.messageEncoding, @@ -123,7 +123,7 @@ public final class Server { return channel.pipeline.addHandler(protocolSwitcher) } } - + // Enable TCP_NODELAY and SO_REUSEADDR for the accepted Channels .childChannelOption(ChannelOptions.socket(IPPROTO_TCP, TCP_NODELAY), value: 1) .childChannelOption(ChannelOptions.socket(SocketOptionLevel(SOL_SOCKET), SO_REUSEADDR), value: 1) @@ -207,10 +207,15 @@ extension Server { /// streaming and bidirectional streaming RPCs) by passing setting `compression` to `.disabled` /// in `sendResponse(_:compression)`. public var messageEncoding: ServerMessageEncoding - + /// The HTTP/2 flow control target window size. public var httpTargetWindowSize: Int + /// The root server logger. Accepted connections will branch from this logger and RPCs on + /// each connection will use a logger branched from the connections logger. This logger is made + /// available to service providers via `context`. Defaults to a no-op logger. + public var logger: Logger + /// Create a `Configuration` with some pre-defined defaults. /// /// - Parameter target: The target to bind to. @@ -223,16 +228,18 @@ extension Server { /// - Parameter connectionIdleTimeout: The amount of time to wait before closing the connection, defaulting to 5 minutes. /// - Parameter messageEncoding: Message compression configuration, defaulting to no compression. /// - Parameter httpTargetWindowSize: The HTTP/2 flow control target window size. + /// - Parameter logger: A logger. Defaults to a no-op logger. public init( target: BindTarget, eventLoopGroup: EventLoopGroup, serviceProviders: [CallHandlerProvider], - errorDelegate: ServerErrorDelegate? = LoggingServerErrorDelegate.shared, + errorDelegate: ServerErrorDelegate? = nil, tls: TLS? = nil, connectionKeepalive: ServerConnectionKeepalive = ServerConnectionKeepalive(), connectionIdleTimeout: TimeAmount = .minutes(5), messageEncoding: ServerMessageEncoding = .disabled, - httpTargetWindowSize: Int = 65535 + httpTargetWindowSize: Int = 65535, + logger: Logger = Logger(label: "io.grpc", factory: { _ in SwiftLogNoOpLogHandler() }) ) { self.target = target self.eventLoopGroup = eventLoopGroup @@ -243,6 +250,7 @@ extension Server { self.connectionIdleTimeout = connectionIdleTimeout self.messageEncoding = messageEncoding self.httpTargetWindowSize = httpTargetWindowSize + self.logger = logger } } } diff --git a/Sources/GRPC/ServerBuilder.swift b/Sources/GRPC/ServerBuilder.swift index 0e3e60598..cddca6b8c 100644 --- a/Sources/GRPC/ServerBuilder.swift +++ b/Sources/GRPC/ServerBuilder.swift @@ -15,6 +15,7 @@ */ import NIO import NIOSSL +import Logging extension Server { public class Builder { @@ -26,6 +27,7 @@ extension Server { private var connectionKeepalive: ServerConnectionKeepalive = ServerConnectionKeepalive() private var connectionIdleTimeout: TimeAmount = .minutes(5) private var httpTargetWindowSize: Int = 65535 + private var logger: Logger = Logger(label: "io.grpc", factory: { _ in SwiftLogNoOpLogHandler() }) fileprivate init(group: EventLoopGroup) { self.group = group @@ -56,7 +58,8 @@ extension Server { connectionKeepalive: self.connectionKeepalive, connectionIdleTimeout: self.connectionIdleTimeout, messageEncoding: self.messageEncoding, - httpTargetWindowSize: self.httpTargetWindowSize + httpTargetWindowSize: self.httpTargetWindowSize, + logger: self.logger ) return Server.start(configuration: configuration) } @@ -138,6 +141,17 @@ extension Server.Builder { } } +extension Server.Builder { + /// Sets the root server logger. Accepted connections will branch from this logger and RPCs on + /// each connection will use a logger branched from the connections logger. This logger is made + /// available to service providers via `context`. Defaults to a no-op logger. + @discardableResult + public func withLogger(_ logger: Logger) -> Self { + self.logger = logger + return self + } +} + extension Server { /// Returns an insecure `Server` builder which is *not configured with TLS*. public static func insecure(group: EventLoopGroup) -> Builder { diff --git a/Sources/GRPC/_GRPCClientChannelHandler.swift b/Sources/GRPC/_GRPCClientChannelHandler.swift index 7d38150a4..be3748259 100644 --- a/Sources/GRPC/_GRPCClientChannelHandler.swift +++ b/Sources/GRPC/_GRPCClientChannelHandler.swift @@ -199,12 +199,16 @@ extension _GRPCRequestHead { scheme: String, path: String, host: String, - requestID: String, - options: CallOptions + options: CallOptions, + requestID: String? ) { - var customMetadata = options.customMetadata - if let requestIDHeader = options.requestIDHeader { + let metadata: HPACKHeaders + if let requestID = requestID, let requestIDHeader = options.requestIDHeader { + var customMetadata = options.customMetadata customMetadata.add(name: requestIDHeader, value: requestID) + metadata = customMetadata + } else { + metadata = options.customMetadata } self = _GRPCRequestHead( @@ -213,7 +217,7 @@ extension _GRPCRequestHead { path: path, host: host, deadline: options.timeLimit.makeDeadline(), - customMetadata: customMetadata, + customMetadata: metadata, encoding: options.messageEncoding ) } diff --git a/Sources/GRPCInteroperabilityTestsImplementation/InteroperabilityTestServer.swift b/Sources/GRPCInteroperabilityTestsImplementation/InteroperabilityTestServer.swift index 9115d7bd6..fcbe49e99 100644 --- a/Sources/GRPCInteroperabilityTestsImplementation/InteroperabilityTestServer.swift +++ b/Sources/GRPCInteroperabilityTestsImplementation/InteroperabilityTestServer.swift @@ -17,6 +17,7 @@ import Foundation import GRPC import NIO import NIOSSL +import Logging /// Makes a server for gRPC interoperability testing. /// @@ -35,7 +36,8 @@ public func makeInteroperabilityTestServer( port: Int, eventLoopGroup: EventLoopGroup, serviceProviders: [CallHandlerProvider] = [TestServiceProvider()], - useTLS: Bool + useTLS: Bool, + logger: Logger? = nil ) throws -> EventLoopFuture { let builder: Server.Builder @@ -52,6 +54,10 @@ public func makeInteroperabilityTestServer( builder = Server.insecure(group: eventLoopGroup) } + if let logger = logger { + builder.withLogger(logger) + } + return builder .withMessageCompression(.enabled(.init(decompressionLimit: .absolute(1024 * 1024)))) .withServiceProviders(serviceProviders) diff --git a/Sources/GRPCPerformanceTests/Benchmarks/EmbeddedClientThroughput.swift b/Sources/GRPCPerformanceTests/Benchmarks/EmbeddedClientThroughput.swift index 3fc962cbd..c8d6f8354 100644 --- a/Sources/GRPCPerformanceTests/Benchmarks/EmbeddedClientThroughput.swift +++ b/Sources/GRPCPerformanceTests/Benchmarks/EmbeddedClientThroughput.swift @@ -38,7 +38,7 @@ class EmbeddedClientThroughput: Benchmark { } func setUp() throws { - self.logger = Logger(label: "io.grpc.testing") + self.logger = Logger(label: "io.grpc.testing", factory: { _ in SwiftLogNoOpLogHandler() }) self.requestHead = _GRPCRequestHead( method: "POST", From 4b498d10af2ec672b94f8cce00dc176eeedf47cd Mon Sep 17 00:00:00 2001 From: George Barnett Date: Mon, 20 Jul 2020 14:41:38 +0100 Subject: [PATCH 2/3] non optional logger --- Sources/GRPC/PlatformSupport.swift | 34 +++++++++++++++--------------- 1 file changed, 17 insertions(+), 17 deletions(-) diff --git a/Sources/GRPC/PlatformSupport.swift b/Sources/GRPC/PlatformSupport.swift index cc00b281c..2dc7b1f77 100644 --- a/Sources/GRPC/PlatformSupport.swift +++ b/Sources/GRPC/PlatformSupport.swift @@ -151,24 +151,24 @@ public enum PlatformSupport { public static func makeEventLoopGroup( loopCount: Int, networkPreference: NetworkPreference = .best, - logger: Logger? = nil + logger: Logger = Logger(label: "io.grpc", factory: { _ in SwiftLogNoOpLogHandler() }) ) -> EventLoopGroup { - logger?.debug("making EventLoopGroup for \(networkPreference) network preference") + logger.debug("making EventLoopGroup for \(networkPreference) network preference") switch networkPreference.implementation.wrapped { case .networkFramework: #if canImport(Network) guard #available(OSX 10.14, iOS 12.0, tvOS 12.0, watchOS 6.0, *) else { - logger?.critical("Network.framework can be imported but is not supported on this platform") + logger.critical("Network.framework can be imported but is not supported on this platform") // This is gated by the availability of `.networkFramework` so should never happen. fatalError(".networkFramework is being used on an unsupported platform") } - logger?.debug("created NIOTSEventLoopGroup for \(networkPreference) preference") + logger.debug("created NIOTSEventLoopGroup for \(networkPreference) preference") return NIOTSEventLoopGroup(loopCount: loopCount) #else fatalError(".networkFramework is being used on an unsupported platform") #endif case .posix: - logger?.debug("created MultiThreadedEventLoopGroup for \(networkPreference) preference") + logger.debug("created MultiThreadedEventLoopGroup for \(networkPreference) preference") return MultiThreadedEventLoopGroup(numberOfThreads: loopCount) } } @@ -181,22 +181,22 @@ public enum PlatformSupport { /// - Parameter group: The `EventLoopGroup` to use. public static func makeClientBootstrap( group: EventLoopGroup, - logger: Logger? = nil + logger: Logger = Logger(label: "io.grpc", factory: { _ in SwiftLogNoOpLogHandler() }) ) -> ClientBootstrapProtocol { - logger?.debug("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 { - logger?.debug("Network.framework is available and the group is correctly typed, creating a NIOTSConnectionBootstrap") + logger.debug("Network.framework is available and the group is correctly typed, creating a NIOTSConnectionBootstrap") return NIOTSConnectionBootstrap(group: tsGroup) } else if let qosEventLoop = group as? QoSEventLoop { - logger?.debug("Network.framework is available and the group is correctly typed, creating a NIOTSConnectionBootstrap") + logger.debug("Network.framework is available and the group is correctly typed, creating a NIOTSConnectionBootstrap") return NIOTSConnectionBootstrap(group: qosEventLoop) } - logger?.debug("Network.framework is available but the group is not typed for NIOTS, falling back to ClientBootstrap") + logger.debug("Network.framework is available but the group is not typed for NIOTS, falling back to ClientBootstrap") } #endif - logger?.debug("creating a ClientBootstrap") + logger.debug("creating a ClientBootstrap") return ClientBootstrap(group: group) } @@ -208,22 +208,22 @@ public enum PlatformSupport { /// - Parameter group: The `EventLoopGroup` to use. public static func makeServerBootstrap( group: EventLoopGroup, - logger: Logger? = nil + logger: Logger = Logger(label: "io.grpc", factory: { _ in SwiftLogNoOpLogHandler() }) ) -> ServerBootstrapProtocol { - logger?.debug("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 { - logger?.debug("Network.framework is available and the group is correctly typed, creating a NIOTSListenerBootstrap") + logger.debug("Network.framework is available and the group is correctly typed, creating a NIOTSListenerBootstrap") return NIOTSListenerBootstrap(group: tsGroup) } else if let qosEventLoop = group as? QoSEventLoop { - logger?.debug("Network.framework is available and the group is correctly typed, creating a NIOTSListenerBootstrap") + logger.debug("Network.framework is available and the group is correctly typed, creating a NIOTSListenerBootstrap") return NIOTSListenerBootstrap(group: qosEventLoop) } - logger?.debug("Network.framework is available but the group is not typed for NIOTS, falling back to ServerBootstrap") + logger.debug("Network.framework is available but the group is not typed for NIOTS, falling back to ServerBootstrap") } #endif - logger?.debug("creating a ServerBootstrap") + logger.debug("creating a ServerBootstrap") return ServerBootstrap(group: group) } } From 3c4b5949bedf90fe7fea5210a9671114eabeed4f Mon Sep 17 00:00:00 2001 From: George Barnett Date: Mon, 20 Jul 2020 14:58:15 +0100 Subject: [PATCH 3/3] autogenerate request ids by default --- Sources/GRPC/ClientOptions.swift | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/Sources/GRPC/ClientOptions.swift b/Sources/GRPC/ClientOptions.swift index 8c0398799..fe18da2b0 100644 --- a/Sources/GRPC/ClientOptions.swift +++ b/Sources/GRPC/ClientOptions.swift @@ -44,7 +44,7 @@ public struct CallOptions { /// Whether the call is cacheable. public var cacheable: Bool - /// How IDs should be provided for requests. Defaults to `.none`. + /// How IDs should be provided for requests. Defaults to `.autogenerated`. /// /// The request ID is used for logging and will be added to the headers of a call if /// `requestIDHeader` is specified. @@ -71,7 +71,7 @@ public struct CallOptions { customMetadata: HPACKHeaders = HPACKHeaders(), timeLimit: TimeLimit = .none, messageEncoding: ClientMessageEncoding = .disabled, - requestIDProvider: RequestIDProvider = .none, + requestIDProvider: RequestIDProvider = .autogenerated, requestIDHeader: String? = nil, cacheable: Bool = false, logger: Logger = Logger(label: "io.grpc", factory: { _ in SwiftLogNoOpLogHandler() })