chore: Add debug logging (#373)

src/core-manager/index.js

@@ -8,6 +8,7 @@ import { HaveExtension, ProjectExtension } from '../generated/extensions.js'
 import { CoreIndex } from './core-index.js'
 import { ReplicationStateMachine } from './replication-state-machine.js'
 import * as rle from './bitfield-rle.js'
+import { Logger } from '../logger.js'
 
 // WARNING: Changing these will break things for existing apps, since namespaces
 // are used for key derivation
@@ -54,6 +55,8 @@ export class CoreManager extends TypedEmitter {
   #state = 'opened'
   #ready
   #haveExtension
+  #deviceId
+  #l
 
   static get namespaces() {
     return NAMESPACES
@@ -67,6 +70,7 @@ export class CoreManager extends TypedEmitter {
    * @param {Buffer} [options.projectSecretKey] 32-byte secret key of the project creator core
    * @param {Partial<Record<Namespace, Buffer>>} [options.encryptionKeys] Encryption keys for each namespace
    * @param {import('hypercore').HypercoreStorage} options.storage Folder to store all hypercore data
+   * @param {Logger} [options.logger]
    */
   constructor({
     sqlite,
@@ -75,6 +79,7 @@ export class CoreManager extends TypedEmitter {
     projectSecretKey,
     encryptionKeys = {},
     storage,
+    logger,
   }) {
     super()
     assert(
@@ -85,7 +90,9 @@ export class CoreManager extends TypedEmitter {
       !projectSecretKey || projectSecretKey.length === 64,
       'project owner core secret key must be 64-byte buffer'
     )
+    this.#l = Logger.create('coreManager', logger)
     const primaryKey = keyManager.getDerivedKey('primaryKey', projectKey)
+    this.#deviceId = keyManager.getIdentityKeypair().publicKey.toString('hex')
     this.#projectKey = projectKey
     this.#encryptionKeys = encryptionKeys
 
@@ -157,7 +164,15 @@ export class CoreManager extends TypedEmitter {
 
     this.#ready = Promise.all(
       [...this.#coreIndex].map(({ core }) => core.ready())
-    ).catch(() => {})
+    )
+      .then(() => {
+        this.#l.log('ready')
+      })
+      .catch(() => {})
+  }
+
+  get deviceId() {
+    return this.#deviceId
   }
 
   get creatorCore() {
@@ -304,6 +319,12 @@ export class CoreManager extends TypedEmitter {
       this.#addCoreSqlStmt.run({ publicKey: key, namespace })
     }
 
+    this.#l.log(
+      'Added %s %s core %k',
+      persist ? 'remote' : writer ? 'local' : 'creator',
+      namespace,
+      key
+    )
     this.emit('add-core', { core, key, namespace })
 
     return { core, key, namespace }

src/discovery/dns-sd.js

@@ -1,10 +1,9 @@
 import { TypedEmitter } from 'tiny-typed-emitter'
 import { Bonjour } from 'bonjour-service'
-// @ts-ignore
-import debug from 'debug'
 import pTimeout from 'p-timeout'
 import { randomBytes } from 'node:crypto'
 import { once } from 'node:events'
+import { Logger } from '../logger.js'
 
 const SERVICE_NAME = 'mapeo'
 
@@ -48,7 +47,7 @@ export class DnsSd extends TypedEmitter {
     }
     /* c8 ignore stop */
     const { name, port } = service
-    this.#log(`service up`, [name, address, port])
+    this.#log('serviceUp', name.slice(0, 7), address, port)
     this.emit('up', { port, name, address })
   }
   /** @param {import('bonjour-service').Service} service */
@@ -74,18 +73,21 @@ export class DnsSd extends TypedEmitter {
   /** @type {Promise<any> | null} */
   #advertisingStopping = null
   #log
+  #l
 
   /**
    *
    * @param {object} [opts]
    * @param {string} [opts.name]
    * @param {boolean} [opts.disableIpv6]
+   * @param {Logger} [opts.logger]
    */
-  constructor({ name, disableIpv6 = true } = {}) {
+  constructor({ name, disableIpv6 = true, logger } = {}) {
     super()
+    this.#l = Logger.create('dnssd', logger)
     this.#name = name || randomBytes(8).toString('hex')
     this.#disableIpv6 = disableIpv6
-    this.#log = debug('mapeo:dnssd:' + this.#name)
+    this.#log = this.#l.log.bind(this.#l)
   }
 
   get name() {

src/discovery/local-discovery.js

@@ -3,11 +3,11 @@ import net from 'node:net'
 import NoiseSecretStream from '@hyperswarm/secret-stream'
 import { once } from 'node:events'
 import { DnsSd } from './dns-sd.js'
-import debug from 'debug'
 import { isPrivate } from 'bogon'
 import StartStopStateMachine from 'start-stop-state-machine'
 import pTimeout from 'p-timeout'
 import { keyToPublicId } from '@mapeo/crypto'
+import { Logger } from '../logger.js'
 
 /** @typedef {{ publicKey: Buffer, secretKey: Buffer }} Keypair */
 /** @typedef {import('../utils.js').OpenedNoiseStream<net.Socket>} OpenedNoiseStream */
@@ -32,21 +32,25 @@ export class LocalDiscovery extends TypedEmitter {
   #log
   /** @type {(e: Error) => void} */
   #handleSocketError
+  #l
 
   /**
    * @param {Object} opts
    * @param {Keypair} opts.identityKeypair
    * @param {DnsSd} [opts.dnssd] Optional DnsSd instance, used for testing
+   * @param {Logger} [opts.logger]
    */
-  constructor({ identityKeypair, dnssd }) {
+  constructor({ identityKeypair, dnssd, logger }) {
     super()
+    this.#l = Logger.create('mdns', logger)
+    this.#log = this.#l.log.bind(this.#l)
     this.#dnssd =
       dnssd ||
       new DnsSd({
         name: keyToPublicId(identityKeypair.publicKey),
+        logger: this.#l,
       })
     this.#dnssd.on('up', this.#handleServiceUp.bind(this))
-    this.#log = debug('mapeo:mdns:' + keyShortname(identityKeypair.publicKey))
     this.#sm = new StartStopStateMachine({
       start: this.#start.bind(this),
       stop: this.#stop.bind(this),
@@ -195,7 +199,8 @@ export class LocalDiscovery extends TypedEmitter {
     this.#log(
       `${isInitiator ? 'outgoing' : 'incoming'} secretSteam connection ${
         isInitiator ? 'to' : 'from'
-      } ${keyShortname(remotePublicKey)}`
+      } %h`,
+      remotePublicKey
     )
 
     const existing = this.#noiseConnections.get(remoteId)
@@ -231,7 +236,7 @@ export class LocalDiscovery extends TypedEmitter {
     this.#noiseConnections.set(remoteId, conn)
 
     conn.on('close', () => {
-      this.#log(`closed connection with ${keyShortname(remotePublicKey)}`)
+      this.#log('closed connection with %h', remotePublicKey)
       this.#noiseConnections.delete(remoteId)
     })
 
@@ -295,13 +300,4 @@ function getAddress(server) {
   return addr
 }
 
-/**
- *
- * @param {Buffer} key
- * @returns
- */
-function keyShortname(key) {
-  return keyToPublicId(key).slice(0, 7)
-}
-
 function noop() {}

src/index-writer/index.js

@@ -3,6 +3,7 @@ import SqliteIndexer from '@mapeo/sqlite-indexer'
 import { getTableConfig } from 'drizzle-orm/sqlite-core'
 import { getBacklinkTableName } from '../schema/utils.js'
 import { discoveryKey } from 'hypercore-crypto'
+import { Logger } from '../logger.js'
 
 /**
  * @typedef {import('../datatype/index.js').MapeoDocTables} MapeoDocTables
@@ -21,15 +22,18 @@ export class IndexWriter {
   /** @type {Map<TTables['_']['name'], SqliteIndexer>} */
   #indexers = new Map()
   #mapDoc
+  #l
   /**
    *
    * @param {object} opts
    * @param {import('better-sqlite3').Database} opts.sqlite
    * @param {TTables[]} opts.tables
    * @param {(doc: MapeoDocInternal, version: import('@mapeo/schema').VersionIdObject) => MapeoDoc} [opts.mapDoc] optionally transform a document prior to indexing. Can also validate, if an error is thrown then the document will not be indexed
    * @param {typeof import('@mapeo/sqlite-indexer').defaultGetWinner} [opts.getWinner] custom function to determine the "winner" of two forked documents. Defaults to choosing the document with the most recent `updatedAt`
+   * @param {Logger} [opts.logger]
    */
-  constructor({ tables, sqlite, mapDoc = (d) => d, getWinner }) {
+  constructor({ tables, sqlite, mapDoc = (d) => d, getWinner, logger }) {
+    this.#l = Logger.create('indexWriter', logger)
     this.#mapDoc = mapDoc
     for (const table of tables) {
       const config = getTableConfig(table)
@@ -63,6 +67,7 @@ export class IndexWriter {
         const version = { coreDiscoveryKey: discoveryKey(key), index }
         var doc = this.#mapDoc(decode(block, version), version)
       } catch (e) {
+        this.#l.log('Could not decode entry %d of %h', index, key)
         // Unknown or invalid entry - silently ignore
         continue
       }
@@ -80,6 +85,16 @@ export class IndexWriter {
         continue
       }
       indexer.batch(docs)
+      if (this.#l.enabled) {
+        for (const doc of docs) {
+          this.#l.log(
+            'Indexed %s %S @ %S',
+            doc.schemaName,
+            doc.docId,
+            doc.versionId
+          )
+        }
+      }
     }
   }
 }