Additional logging for connection pool (#1795)

Motivation:

The connection pool logs information about various states but the logger
doesn't have an id attached for the sub-pool making it hard determine
the state of individual subpools.

Modifications:

- Add the subpool id to the logger metadata
- Add a log when the pool is initialized
- Add a log when the pool can't add any more connections

Result:

Better visibility

Author: glbrntt

Sources/GRPC/ConnectionManager.swift

@@ -248,6 +248,39 @@ internal final class ConnectionManager: @unchecked Sendable {
     }
   }
 
+  /// Returns whether the state is 'connecting'.
+  private var isConnecting: Bool {
+    self.eventLoop.assertInEventLoop()
+    switch self.state {
+    case .connecting:
+      return true
+    case .idle, .transientFailure, .active, .ready, .shutdown:
+      return false
+    }
+  }
+
+  /// Returns whether the state is 'ready'.
+  private var isReady: Bool {
+    self.eventLoop.assertInEventLoop()
+    switch self.state {
+    case .ready:
+      return true
+    case .idle, .active, .connecting, .transientFailure, .shutdown:
+      return false
+    }
+  }
+
+  /// Returns whether the state is 'ready'.
+  private var isTransientFailure: Bool {
+    self.eventLoop.assertInEventLoop()
+    switch self.state {
+    case .transientFailure:
+      return true
+    case .idle, .connecting, .active, .ready, .shutdown:
+      return false
+    }
+  }
+
   /// Returns whether the state is 'shutdown'.
   private var isShutdown: Bool {
     self.eventLoop.assertInEventLoop()
@@ -1140,7 +1173,22 @@ extension ConnectionManager {
       return self.manager.isIdle
     }
 
-    /// Returne `true` if the connection is in the shutdown state.
+    /// Returns `true` if the connection is in the connecting state.
+    internal var isConnecting: Bool {
+      return self.manager.isConnecting
+    }
+
+    /// Returns `true` if the connection is in the ready state.
+    internal var isReady: Bool {
+      return self.manager.isReady
+    }
+
+    /// Returns `true` if the connection is in the transient failure state.
+    internal var isTransientFailure: Bool {
+      return self.manager.isTransientFailure
+    }
+
+    /// Returns `true` if the connection is in the shutdown state.
     internal var isShutdown: Bool {
       return self.manager.isShutdown
     }

Sources/GRPC/ConnectionPool/ConnectionPool.swift

@@ -103,7 +103,7 @@ internal final class ConnectionPool {
 
   /// A logger which always sets "GRPC" as its source.
   @usableFromInline
-  internal let logger: GRPCLogger
+  private(set) var logger: GRPCLogger
 
   /// Returns `NIODeadline` representing 'now'. This is useful for testing.
   @usableFromInline
@@ -139,6 +139,18 @@ internal final class ConnectionPool {
     /// The ID of waiter.
     @usableFromInline
     static let waiterID = "pool.waiter.id"
+    /// The maximum number of connections allowed in the pool.
+    @usableFromInline
+    static let connectionsMax = "pool.connections.max"
+    /// The number of connections in the ready state.
+    @usableFromInline
+    static let connectionsReady = "pool.connections.ready"
+    /// The number of connections in the connecting state.
+    @usableFromInline
+    static let connectionsConnecting = "pool.connections.connecting"
+    /// The number of connections in the transient failure state.
+    @usableFromInline
+    static let connectionsTransientFailure = "pool.connections.transientFailure"
   }
 
   @usableFromInline
@@ -158,6 +170,7 @@ internal final class ConnectionPool {
       (0.0 ... 1.0).contains(reservationLoadThreshold),
       "reservationLoadThreshold must be within the range 0.0 ... 1.0"
     )
+
     self.reservationLoadThreshold = reservationLoadThreshold
     self.assumedMaxConcurrentStreams = assumedMaxConcurrentStreams
 
@@ -179,6 +192,14 @@ internal final class ConnectionPool {
   /// - Parameter connections: The number of connections to add to the pool.
   internal func initialize(connections: Int) {
     assert(self._connections.isEmpty)
+    self.logger.logger[metadataKey: Metadata.id] = "\(ObjectIdentifier(self))"
+    self.logger.debug(
+      "initializing new sub-pool",
+      metadata: [
+        Metadata.waitersMax: .stringConvertible(self.maxWaiters),
+        Metadata.connectionsMax: .stringConvertible(connections),
+      ]
+    )
     self._connections.reserveCapacity(connections)
     while self._connections.count < connections {
       self.addConnectionToPool()
@@ -461,6 +482,20 @@ internal final class ConnectionPool {
   internal func _startConnectingIdleConnection() {
     if let index = self._connections.values.firstIndex(where: { $0.manager.sync.isIdle }) {
       self._connections.values[index].manager.sync.startConnecting()
+    } else {
+      let connecting = self._connections.values.count { $0.manager.sync.isConnecting }
+      let ready = self._connections.values.count { $0.manager.sync.isReady }
+      let transientFailure = self._connections.values.count { $0.manager.sync.isTransientFailure }
+
+      self.logger.debug(
+        "no idle connections in pool",
+        metadata: [
+          Metadata.connectionsConnecting: .stringConvertible(connecting),
+          Metadata.connectionsReady: .stringConvertible(ready),
+          Metadata.connectionsTransientFailure: .stringConvertible(transientFailure),
+          Metadata.waitersCount: .stringConvertible(self.waiters.count),
+        ]
+      )
     }
   }
 
@@ -965,3 +1000,11 @@ extension GRPCConnectionPoolError: GRPCStatusTransformable {
     }
   }
 }
+
+extension Sequence {
+  fileprivate func count(where predicate: (Element) -> Bool) -> Int {
+    return self.reduce(0) { count, element in
+      predicate(element) ? count + 1 : count
+    }
+  }
+}