chore: debug logging improvements

package.json

@@ -142,6 +142,7 @@
     "random-access-file": "^4.0.7",
     "random-access-memory": "^6.2.1",
     "rimraf": "^5.0.5",
+    "supports-color": "^9.4.0",
     "tempy": "^3.1.0",
     "ts-proto": "^1.156.7",
     "typedoc": "^0.26.7",

src/core-manager/index.js

@@ -33,8 +33,8 @@ export const kCoreManagerReplicate = Symbol('replicate core manager')
 export class CoreManager extends TypedEmitter {
   #corestore
   #coreIndex
-  /** @type {Core} */
-  #creatorCore
+  /** @type {CoreRecord} */
+  #creatorCoreRecord
   #projectKey
   #queries
   #encryptionKeys
@@ -128,20 +128,20 @@ export class CoreManager extends TypedEmitter {
       }
       const writer = this.#addCore(keyPair, namespace)
       if (namespace === 'auth' && projectSecretKey) {
-        this.#creatorCore = writer.core
+        this.#creatorCoreRecord = writer
       }
     }
 
     // For anyone other than the project creator, creatorCore is readonly
-    this.#creatorCore ??= this.#addCore({ publicKey: projectKey }, 'auth').core
+    this.#creatorCoreRecord ??= this.#addCore({ publicKey: projectKey }, 'auth')
 
     // Load persisted cores
     const rows = db.select().from(coresTable).all()
     for (const { publicKey, namespace } of rows) {
       this.#addCore({ publicKey }, namespace)
     }
 
-    this.#projectExtension = this.#creatorCore.registerExtension(
+    this.#projectExtension = this.creatorCore.registerExtension(
       'mapeo/project',
       {
         encoding: ProjectExtensionCodec,
@@ -151,14 +151,14 @@ export class CoreManager extends TypedEmitter {
       }
     )
 
-    this.#haveExtension = this.#creatorCore.registerExtension('mapeo/have', {
+    this.#haveExtension = this.creatorCore.registerExtension('mapeo/have', {
       encoding: HaveExtensionCodec,
       onmessage: (msg, peer) => {
         this.#handleHaveMessage(msg, peer)
       },
     })
 
-    this.#creatorCore.on('peer-add', (peer) => {
+    this.creatorCore.on('peer-add', (peer) => {
       this.#sendHaves(peer, this.#coreIndex).catch(() => {
         this.#l.log('Failed to send pre-haves to newly-connected peer')
       })
@@ -179,7 +179,11 @@ export class CoreManager extends TypedEmitter {
   }
 
   get creatorCore() {
-    return this.#creatorCore
+    return this.#creatorCoreRecord.core
+  }
+
+  get creatorCoreRecord() {
+    return this.#creatorCoreRecord
   }
 
   /**
@@ -255,7 +259,6 @@ export class CoreManager extends TypedEmitter {
    * @returns {CoreRecord}
    */
   addCore(key, namespace) {
-    this.#l.log('Adding remote core %k to %s', key, namespace)
     return this.#addCore({ publicKey: key }, namespace, true)
   }
 
@@ -298,7 +301,7 @@ export class CoreManager extends TypedEmitter {
 
     if (writer) {
       const sendHaves = debounce(WRITER_CORE_PREHAVES_DEBOUNCE_DELAY, () => {
-        for (const peer of this.#creatorCore.peers) {
+        for (const peer of this.creatorCore.peers) {
           this.#sendHaves(peer, [{ core, namespace }]).catch(() => {
             this.#l.log('Failed to send new pre-haves to other peers')
           })

src/index-writer/index.js

@@ -97,7 +97,7 @@ export class IndexWriter {
       const indexer = this.#indexers.get(schemaName)
       if (!indexer) continue // Won't happen, but TS doesn't know that
       indexer.batch(docs)
-      if (this.#l.enabled) {
+      if (this.#l.log.enabled) {
         for (const doc of docs) {
           this.#l.log(
             'Indexed %s %S @ %S',

src/logger.js

@@ -5,6 +5,32 @@ import util from 'util'
 
 const TRIM = 7
 
+const selectColorOriginal = createDebug.selectColor
+
+/**
+ * Selects a color for a debug namespace (warning: overrides private api).
+ * Rather than the default behaviour of creating a unique color for each
+ * namespace, we only hash the last 7 characters of the namespace, which is the
+ * deviceId. This results in debug output where each deviceId has a different
+ * colour, which is more useful for debugging.
+ * @param {string} namespace The namespace string for the debug instance to be colored
+ * @return {number|string} An ANSI color code for the given namespace
+ */
+createDebug.selectColor = function (namespace) {
+  if (!namespace.startsWith('mapeo:')) {
+    return selectColorOriginal(namespace)
+  }
+  let hash = 0
+
+  for (let i = namespace.length - TRIM - 1; i < namespace.length; i++) {
+    hash = (hash << 5) - hash + namespace.charCodeAt(i)
+    hash |= 0 // Convert to 32bit integer
+  }
+
+  // @ts-expect-error - private debug api
+  return createDebug.colors[Math.abs(hash) % createDebug.colors.length]
+}
+
 createDebug.formatters.h = function (v) {
   if (!Buffer.isBuffer(v)) return '[undefined]'
   return v.toString('hex').slice(0, TRIM)
@@ -76,15 +102,8 @@ export class Logger {
     this.#baseLogger = baseLogger || createDebug('mapeo' + (ns ? `:${ns}` : ''))
     this.#log = this.#baseLogger.extend(this.deviceId.slice(0, TRIM))
   }
-  get enabled() {
-    return this.#log.enabled
-  }
-
-  /**
-   * @param  {Parameters<createDebug.Debugger>} args
-   */
-  log = (...args) => {
-    this.#log.apply(this, args)
+  get log() {
+    return this.#log
   }
   /**
    *

src/mapeo-manager.js

@@ -674,6 +674,14 @@ export class MapeoManager extends TypedEmitter {
       isConfigSynced
     ) {
       return true
+    } else {
+      this.#l.log(
+        'Pending initial sync: role %s, projectSettings %o, auth %o, config %o',
+        isRoleSynced,
+        isProjectSettingsSynced,
+        isAuthSynced,
+        isConfigSynced
+      )
     }
     return new Promise((resolve, reject) => {
       /** @param {import('./sync/sync-state.js').State} syncState */

src/mapeo-project.js

@@ -552,7 +552,6 @@ export class MapeoProject extends TypedEmitter {
         await this.#dataTypes.projectSettings.getByDocId(this.#projectId)
       )
     } catch (e) {
-      this.#l.log('No project settings')
       return /** @type {EditableProjectSettings} */ (EMPTY_PROJECT_SETTINGS)
     }
   }

src/sync/peer-sync-controller.js

@@ -32,6 +32,7 @@ export class PeerSyncController {
   #downloadingRanges = new Map()
   /** @type {SyncStatus} */
   #prevSyncStatus = createNamespaceMap('unknown')
+  /** @type {import('debug').Debugger} */
   #log
 
   /**
@@ -43,25 +44,27 @@ export class PeerSyncController {
    * @param {Logger} [opts.logger]
    */
   constructor({ protomux, coreManager, syncState, roles, logger }) {
-    /**
-     * @param {string} formatter
-     * @param {unknown[]} args
-     * @returns {void}
-     */
-    this.#log = (formatter, ...args) => {
-      const log = Logger.create('peer', logger).log
-      return log.apply(null, [
-        `[%h] ${formatter}`,
-        protomux.stream.remotePublicKey,
-        ...args,
-      ])
-    }
+    const log = Logger.create('peer', logger).log
+    this.#log = Object.assign(
+      /**
+       * @param {any} formatter
+       * @param  {...any} args
+       */
+      (formatter, ...args) => {
+        return log.apply(null, [
+          `[%h] ${formatter}`,
+          protomux.stream.remotePublicKey,
+          ...args,
+        ])
+      },
+      log
+    )
     this.#coreManager = coreManager
     this.#protomux = protomux
     this.#roles = roles
 
     // Always need to replicate the project creator core
-    this.#replicateCore(coreManager.creatorCore)
+    this.#replicateCoreRecord(coreManager.creatorCoreRecord)
 
     coreManager.on('add-core', this.#handleAddCore)
     syncState.on('state', this.#handleStateChange)
@@ -98,14 +101,18 @@ export class PeerSyncController {
     // If we already know about this core, then we will add it to the
     // replication stream when we are ready
     if (coreRecord) {
-      this.#log(
-        'Received discovery key %h, but already have core in namespace %s',
-        discoveryKey,
-        coreRecord.namespace
-      )
       if (this.#enabledNamespaces.has(coreRecord.namespace)) {
-        this.#replicateCore(coreRecord.core)
+        this.#replicateCoreRecord(coreRecord)
+      } else {
+        this.#log(
+          'Received discovery key %h, for core %h, but namespace %s is disabled',
+          discoveryKey,
+          coreRecord.key,
+          coreRecord.namespace
+        )
       }
+    } else {
+      this.#log('Received unknown discovery key %h', discoveryKey)
     }
   }
 
@@ -115,9 +122,9 @@ export class PeerSyncController {
    *
    * @param {CoreRecord} coreRecord
    */
-  #handleAddCore = ({ core, namespace }) => {
-    if (!this.#enabledNamespaces.has(namespace)) return
-    this.#replicateCore(core)
+  #handleAddCore = (coreRecord) => {
+    if (!this.#enabledNamespaces.has(coreRecord.namespace)) return
+    this.#replicateCoreRecord(coreRecord)
   }
 
   /**
@@ -235,25 +242,36 @@ export class PeerSyncController {
   }
 
   /**
-   * @param {import('hypercore')<'binary', any>} core
+   * @param {CoreRecord} coreRecord
    */
-  #replicateCore(core) {
+  #replicateCoreRecord({ core, namespace }) {
     if (core.closed) return
     if (this.#replicatingCores.has(core)) return
-    this.#log('replicating core %k', core.key)
+    this.#log('replicating %s core %k', namespace, core.key)
     core.replicate(this.#protomux)
-    core.on('peer-remove', (peer) => {
-      if (!peer.remotePublicKey.equals(this.peerKey)) return
-      this.#log('peer-remove %h from core %k', peer.remotePublicKey, core.key)
-    })
     this.#replicatingCores.add(core)
+
+    if (!this.#log.enabled) return
+
+    /** @type {(peer: any) => void} */
+    const handlePeerRemove = (peer) => {
+      if (!peer.remotePublicKey.equals(this.peerKey)) return
+      core.off('peer-remove', handlePeerRemove)
+      this.#log(
+        'peer-remove %h from %s core %k',
+        peer.remotePublicKey,
+        namespace,
+        core.key
+      )
+    }
+    core.on('peer-remove', handlePeerRemove)
   }
 
   /**
-   * @param {import('hypercore')<'binary', any>} core
+   * @param {CoreRecord} coreRecord
    * @returns {Promise<void>}
    */
-  async #unreplicateCore(core) {
+  async #unreplicateCoreRecord({ core, namespace }) {
     if (core === this.#coreManager.creatorCore) return
 
     this.#replicatingCores.delete(core)
@@ -266,16 +284,16 @@ export class PeerSyncController {
     }
 
     unreplicate(core, this.#protomux)
-    this.#log('unreplicated core %k', core.key)
+    this.#log('unreplicated %s core %k', namespace, core.key)
   }
 
   /**
    * @param {Namespace} namespace
    */
   #enableNamespace(namespace) {
     if (this.#enabledNamespaces.has(namespace)) return
-    for (const { core } of this.#coreManager.getCores(namespace)) {
-      this.#replicateCore(core)
+    for (const coreRecord of this.#coreManager.getCores(namespace)) {
+      this.#replicateCoreRecord(coreRecord)
     }
     this.#enabledNamespaces.add(namespace)
     this.#log('enabled namespace %s', namespace)
@@ -286,8 +304,8 @@ export class PeerSyncController {
    */
   #disableNamespace(namespace) {
     if (!this.#enabledNamespaces.has(namespace)) return
-    for (const { core } of this.#coreManager.getCores(namespace)) {
-      this.#unreplicateCore(core)
+    for (const coreRecord of this.#coreManager.getCores(namespace)) {
+      this.#unreplicateCoreRecord(coreRecord)
     }
     this.#enabledNamespaces.delete(namespace)
     this.#log('disabled namespace %s', namespace)