Use metadata in log messages (#720)

Motivation:

I was analyzing some logs produced by grpc-swift but some of
the messages lack structure, making it more difficult than it
should be to run queries on the logs.

SwiftLog supports structured logging and its API allow us to
log a message and some metadata associated to it.
Keeping the message string constant and logging the variable
pieces of information as metadata, the logs produced by grpc-swift
are going to be more easily analysed and processed.

Modifications:

This commit changes the logging calls where we had a variable
message to have a constant message. The variable pieces of information
are stored as metadata.

Result:

grpc-swift will produce log messages that can be analyzed and processed
more easily.

Sources/GRPC/ClientConnection.swift

@@ -275,7 +275,7 @@ extension ClientConnection {
       return configuration.eventLoopGroup.next().makeFailedFuture(GRPCStatus.processingError)
     }
 
-    logger.debug("attempting to connect to \(configuration.target) on \(eventLoop)")
+    logger.debug("attempting to connect", metadata: ["target": "\(configuration.target)", "event_loop": "\(eventLoop)"])
     connectivity.state = .connecting
     let timeoutAndBackoff = backoffIterator?.next()
 
@@ -327,7 +327,7 @@ extension ClientConnection {
     backoffIterator: ConnectionBackoffIterator?,
     logger: Logger
   ) -> EventLoopFuture<Channel> {
-    logger.debug("scheduling connection attempt in \(timeout) seconds")
+    logger.debug("scheduling connection attempt", metadata: ["delay_seconds": "\(timeout)"])
     // The `futureResult` of the scheduled task is of type
     // `EventLoopFuture<EventLoopFuture<Channel>>`, so we need to `flatMap` it to
     // remove a level of indirection.
@@ -392,7 +392,7 @@ extension ClientConnection {
       }
 
     if let timeout = timeout {
-      logger.debug("setting connect timeout to \(timeout) seconds")
+      logger.debug("setting connect timeout", metadata: ["timeout_seconds" : "\(timeout)"])
       return bootstrap.connectTimeout(.seconds(timeInterval: timeout))
     } else {
       logger.debug("no connect timeout provided")

Sources/GRPC/ConnectivityState.swift

@@ -104,13 +104,13 @@ public class ConnectivityStateMonitor {
   /// - Important: This is **not** thread safe.
   private func setNewState(to newValue: ConnectivityState) {
     if self._userInitiatedShutdown {
-      self.logger.debug("user has initiated shutdown: ignoring new state: \(newValue)")
+      self.logger.debug("user has initiated shutdown: ignoring new state", metadata: ["new_state": "\(newValue)"])
       return
     }
 
     let oldValue = self._state
     if oldValue != newValue {
-      self.logger.debug("connectivity state change: \(oldValue) to \(newValue)")
+      self.logger.debug("connectivity state change", metadata: ["old_state": "\(oldValue)", "new_state": "\(newValue)"])
       self._state = newValue
       self._delegate?.connectivityStateDidChange(from: oldValue, to: newValue)
     }

Sources/GRPC/HTTP1ToGRPCServerCodec.swift

@@ -80,13 +80,13 @@ public final class HTTP1ToGRPCServerCodec<Request: GRPCPayload, Response: GRPCPa
   var inboundState = InboundState.expectingHeaders {
     willSet {
       guard newValue != self.inboundState else { return }
-      self.logger.debug("inbound state changed from \(self.inboundState) to \(newValue)")
+      self.logger.debug("inbound state changed", metadata: ["old_state": "\(self.inboundState)", "new_state": "\(newValue)"])
     }
   }
   var outboundState = OutboundState.expectingHeaders {
     willSet {
       guard newValue != self.outboundState else { return }
-      self.logger.debug("outbound state changed from \(self.outboundState) to \(newValue)")
+      self.logger.debug("outbound state changed", metadata: ["old_state": "\(self.outboundState)", "new_state": "\(newValue)"])
     }
   }
 
@@ -115,7 +115,7 @@ extension HTTP1ToGRPCServerCodec: ChannelInboundHandler {
 
   public func channelRead(context: ChannelHandlerContext, data: NIOAny) {
     if case .ignore = inboundState {
-      self.logger.notice("ignoring read data: \(data)")
+      self.logger.notice("ignoring read data", metadata: ["data": "\(data)"])
       return
     }
 
@@ -139,7 +139,8 @@ extension HTTP1ToGRPCServerCodec: ChannelInboundHandler {
   func processHead(context: ChannelHandlerContext, requestHead: HTTPRequestHead) throws -> InboundState {
     self.logger.debug("processing request head", metadata: ["head": "\(requestHead)"])
     guard case .expectingHeaders = inboundState else {
-      self.logger.error("invalid state '\(inboundState)' while processing request head", metadata: ["head": "\(requestHead)"])
+      self.logger.error("invalid state while processing request head",
+                        metadata: ["state": "\(inboundState)", "head": "\(requestHead)"])
       throw GRPCError.InvalidState("expected state .expectingHeaders, got \(inboundState)").captureContext()
     }
 
@@ -169,7 +170,8 @@ extension HTTP1ToGRPCServerCodec: ChannelInboundHandler {
   func processBody(context: ChannelHandlerContext, body: inout ByteBuffer) throws -> InboundState {
     self.logger.debug("processing body: \(body)")
     guard case .expectingBody = inboundState else {
-      self.logger.error("invalid state '\(inboundState)' while processing body", metadata: ["body": "\(body)"])
+      self.logger.error("invalid state while processing body",
+                        metadata: ["state": "\(inboundState)", "body": "\(body)"])
       throw GRPCError.InvalidState("expected state .expectingBody, got \(inboundState)").captureContext()
     }
 
@@ -235,7 +237,8 @@ extension HTTP1ToGRPCServerCodec: ChannelOutboundHandler {
     switch self.unwrapOutboundIn(data) {
     case .headers(var headers):
       guard case .expectingHeaders = self.outboundState else {
-        self.logger.error("invalid state '\(self.outboundState)' while writing headers", metadata: ["headers": "\(headers)"])
+        self.logger.error("invalid state while writing headers",
+                          metadata: ["state": "\(self.outboundState)", "headers": "\(headers)"])
         return
       }
 
@@ -256,7 +259,7 @@ extension HTTP1ToGRPCServerCodec: ChannelOutboundHandler {
 
     case .message(let message):
       guard case .expectingBodyOrStatus = self.outboundState else {
-        self.logger.error("invalid state '\(self.outboundState)' while writing message")
+        self.logger.error("invalid state while writing message", metadata: ["state": "\(self.outboundState)"])
         return
       }
       

Sources/GRPC/HTTPProtocolSwitcher.swift

@@ -36,7 +36,7 @@ internal class HTTPProtocolSwitcher {
 
   private var state: State = .notConfigured {
     willSet {
-      self.logger.debug("state changed from '\(self.state)' to '\(newValue)'")
+      self.logger.debug("state changed", metadata: ["old_state": "\(self.state)", "new_state": "\(newValue)"])
     }
   }
   private var bufferedData: [NIOAny] = []
@@ -74,7 +74,7 @@ extension HTTPProtocolSwitcher: ChannelInboundHandler, RemovableChannelHandler {
     case .notConfigured:
       self.logger.debug("determining http protocol version")
       self.state = .configuring
-      self.logger.debug("buffering data \(data)")
+      self.logger.debug("buffering data", metadata: ["data": "\(data)"])
       self.bufferedData.append(data)
 
       // Detect the HTTP protocol version for the incoming request, or error out if it
@@ -141,7 +141,7 @@ extension HTTPProtocolSwitcher: ChannelInboundHandler, RemovableChannelHandler {
       }
 
     case .configuring:
-      self.logger.debug("buffering data \(data)")
+      self.logger.debug("buffering data", metadata: ["data": "\(data)"])
       self.bufferedData.append(data)
 
     case .configured:

Sources/GRPC/SettingsObservingHandler.swift

@@ -40,7 +40,9 @@ class InitialSettingsObservingHandler: ChannelInboundHandler, RemovableChannelHa
       self.connectivityStateMonitor.state = .ready
 
       let remoteAddressDescription = context.channel.remoteAddress.map { "\($0)" } ?? "n/a"
-      self.logger.info("gRPC connection to \(remoteAddressDescription) on \(context.eventLoop) ready")
+      self.logger.info("gRPC connection ready", metadata: [
+        "remote_address": "\(remoteAddressDescription)",
+        "event_loop": "\(context.eventLoop)"])
 
       // We're no longer needed at this point, remove ourselves from the pipeline.
       self.logger.debug("removing 'InitialSettingsObservingHandler' from the channel")