fix: reduce dht logging and update metrics (#2725)

Make some more verbose logging trace logging and switch metrics to
use separate operation/error metrics.

Refs: https://promlabs.com/blog/2023/09/19/errors-successes-totals-which-metrics-should-i-expose-to-prometheus/

Author: achingbrain

packages/kad-dht/src/kad-dht.ts

@@ -333,12 +333,12 @@ export class KadDHT extends TypedEventEmitter<PeerDiscoveryEvents> implements Ka
   }
 
   async onPeerConnect (peerData: PeerInfo): Promise<void> {
-    this.log('peer %p connected', peerData.id)
+    this.log.trace('peer %p connected', peerData.id)
 
     peerData = this.peerInfoMapper(peerData)
 
     if (peerData.multiaddrs.length === 0) {
-      this.log('ignoring %p as there were no valid addresses in %s after filtering', peerData.id, peerData.multiaddrs.map(addr => addr.toString()))
+      this.log.trace('ignoring %p as there were no valid addresses in %s after filtering', peerData.id, peerData.multiaddrs.map(addr => addr.toString()))
       return
     }
 
@@ -366,7 +366,12 @@ export class KadDHT extends TypedEventEmitter<PeerDiscoveryEvents> implements Ka
   /**
    * If 'server' this node will respond to DHT queries, if 'client' this node will not
    */
-  async setMode (mode: 'client' | 'server'): Promise<void> {
+  async setMode (mode: 'client' | 'server', force = false): Promise<void> {
+    if (mode === this.getMode() && !force) {
+      this.log('already in %s mode', mode)
+      return
+    }
+
     await this.components.registrar.unhandle(this.protocol)
 
     if (mode === 'client') {
@@ -389,7 +394,7 @@ export class KadDHT extends TypedEventEmitter<PeerDiscoveryEvents> implements Ka
     this.running = true
 
     // Only respond to queries when not in client mode
-    await this.setMode(this.clientMode ? 'client' : 'server')
+    await this.setMode(this.clientMode ? 'client' : 'server', true)
 
     await start(
       this.querySelf,

packages/kad-dht/src/network.ts

@@ -122,7 +122,13 @@ export class Network extends TypedEventEmitter<NetworkEvents> implements Startab
       }, options)
     } catch (err: any) {
       stream?.abort(err)
-      this.log.error('could not send %s to %p', msg.type, to, err)
+
+      // only log if the incoming signal was not aborted - this means we were
+      // no longer interested in the query result
+      if (options.signal?.aborted !== true) {
+        this.log.error('could not send %s to %p - %e', msg.type, to, err)
+      }
+
       yield queryErrorEvent({ from: to, error: err }, options)
     } finally {
       this.timeout.cleanUp(signal)

packages/kad-dht/src/query/query-path.ts

@@ -135,7 +135,7 @@ export async function * queryPath (options: QueryPathOptions): AsyncGenerator<Qu
           if (event.name === 'PEER_RESPONSE') {
             for (const closerPeer of event.closer) {
               if (peersSeen.has(closerPeer.id)) { // eslint-disable-line max-depth
-                log('already seen %p in query', closerPeer.id)
+                log.trace('already seen %p in query', closerPeer.id)
                 continue
               }
 
@@ -154,11 +154,11 @@ export async function * queryPath (options: QueryPathOptions): AsyncGenerator<Qu
 
               // only continue query if closer peer is actually closer
               if (uint8ArrayXorCompare(closerPeerXor, peerXor) !== -1) { // eslint-disable-line max-depth
-                log('skipping %p as they are not closer to %b than %p', closerPeer.id, key, peer)
+                log.trace('skipping %p as they are not closer to %b than %p', closerPeer.id, key, peer)
                 continue
               }
 
-              log('querying closer peer %p', closerPeer.id)
+              log.trace('querying closer peer %p', closerPeer.id)
               queryPeer(closerPeer.id, closerPeerKadId)
             }
           }

packages/kad-dht/src/routing-table/index.ts

@@ -346,7 +346,7 @@ export class RoutingTable extends TypedEventEmitter<RoutingTableEvents> implemen
 
     this.kb.add({ kadId, peerId })
 
-    this.log('added %p with kad id %b', peerId, kadId)
+    this.log.trace('added %p with kad id %b', peerId, kadId)
 
     this.updateMetrics()
   }

packages/kad-dht/src/rpc/handlers/add-provider.ts

@@ -27,8 +27,6 @@ export class AddProviderHandler implements DHTMessageHandler {
   }
 
   async handle (peerId: PeerId, msg: Message): Promise<Message | undefined> {
-    this.log('start')
-
     if (msg.key == null || msg.key.length === 0) {
       throw new InvalidMessageError('Missing key')
     }
@@ -45,6 +43,8 @@ export class AddProviderHandler implements DHTMessageHandler {
       this.log.error('no providers found in message')
     }
 
+    this.log('%p asked us to store provider record for for %c', peerId, cid)
+
     await Promise.all(
       msg.providers.map(async (pi) => {
         // Ignore providers not from the originator
@@ -58,7 +58,7 @@ export class AddProviderHandler implements DHTMessageHandler {
           return
         }
 
-        this.log('received provider %p for %s (addrs %s)', peerId, cid, pi.multiaddrs.map((m) => multiaddr(m).toString()))
+        this.log.trace('received provider %p for %s (addrs %s)', peerId, cid, pi.multiaddrs.map((m) => multiaddr(m).toString()))
 
         const multihash = Digest.decode(pi.id)
 

packages/kad-dht/src/rpc/index.ts

@@ -35,11 +35,17 @@ export class RPC {
   private readonly handlers: Record<string, DHTMessageHandler>
   private readonly routingTable: RoutingTable
   private readonly log: Logger
-  private readonly metrics?: CounterGroup
+  private readonly metrics: {
+    operations?: CounterGroup
+    errors?: CounterGroup
+  }
 
   constructor (components: RPCComponents, init: RPCInit) {
     const { providers, peerRouting, validators, logPrefix, peerInfoMapper } = init
-    this.metrics = components.metrics?.registerCounterGroup(`${logPrefix.replaceAll(':', '_')}_inbound_rpc_requests`)
+    this.metrics = {
+      operations: components.metrics?.registerCounterGroup(`${logPrefix.replaceAll(':', '_')}_inbound_rpc_requests_total`),
+      errors: components.metrics?.registerCounterGroup(`${logPrefix.replaceAll(':', '_')}_inbound_rpc_errors_total`)
+    }
 
     this.log = components.logger.forComponent(`${logPrefix}:rpc`)
     this.routingTable = init.routingTable
@@ -72,16 +78,14 @@ export class RPC {
     }
 
     try {
-      const value = await handler.handle(peerId, msg)
-
-      this.metrics?.increment({
-        [`${msg.type}_SUCCESS`]: true
+      this.metrics.operations?.increment({
+        [msg.type]: true
       })
 
-      return value
+      return await handler.handle(peerId, msg)
     } catch {
-      this.metrics?.increment({
-        [`${msg.type}_ERROR`]: true
+      this.metrics.errors?.increment({
+        [msg.type]: true
       })
     }
   }

packages/kad-dht/test/kad-dht.spec.ts

@@ -135,8 +135,8 @@ describe('KadDHT', () => {
       expect(registrarHandleSpy).to.have.property('callCount', 1)
 
       await dht.setMode('server')
-      // we were already in server mode
-      expect(registrarHandleSpy).to.have.property('callCount', 2)
+      // we were already in server mode, should have been a no-op
+      expect(registrarHandleSpy).to.have.property('callCount', 1)
 
       await dht.stop()
     })