From 8e59881993f73f97d44dc76240c0a538901e68ab Mon Sep 17 00:00:00 2001 From: Gregor MacLennan Date: Thu, 3 Oct 2024 12:11:14 +0100 Subject: [PATCH] chore: debug logging improvements --- package-lock.json | 29 +++++++--- package.json | 1 + src/core-manager/index.js | 23 ++++---- src/index-writer/index.js | 2 +- src/logger.js | 37 +++++++++---- src/mapeo-manager.js | 8 +++ src/mapeo-project.js | 1 - src/sync/peer-sync-controller.js | 92 +++++++++++++++++++------------- src/sync/sync-api.js | 8 +-- 9 files changed, 132 insertions(+), 69 deletions(-) diff --git a/package-lock.json b/package-lock.json index 0315935de..35f5c4a86 100644 --- a/package-lock.json +++ b/package-lock.json @@ -93,6 +93,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", @@ -1977,6 +1978,18 @@ "url": "https://github.com/chalk/chalk?sponsor=1" } }, + "node_modules/chalk/node_modules/supports-color": { + "version": "7.2.0", + "resolved": "https://registry.npmjs.org/supports-color/-/supports-color-7.2.0.tgz", + "integrity": "sha512-qpCAvRl9stuOHveKsn7HncJRvv501qIacKzQlO/+Lwxc9+0q2wLyv4Dfvt80/DPn2pqOBsJdDiogXGR9+OvwRw==", + "dev": true, + "dependencies": { + "has-flag": "^4.0.0" + }, + "engines": { + "node": ">=8" + } + }, "node_modules/character-entities-html4": { "version": "2.1.0", "resolved": "https://registry.npmjs.org/character-entities-html4/-/character-entities-html4-2.1.0.tgz", @@ -3905,8 +3918,9 @@ }, "node_modules/has-flag": { "version": "4.0.0", + "resolved": "https://registry.npmjs.org/has-flag/-/has-flag-4.0.0.tgz", + "integrity": "sha512-EykJT/Q1KjTWctppgIAgfSO0tKVuZUjhgMr17kqTumMl6Afv3EISleU7qZUzoXDFTAHTDC4NOoG/ZxU3EvlMPQ==", "dev": true, - "license": "MIT", "engines": { "node": ">=8" } @@ -7694,14 +7708,15 @@ } }, "node_modules/supports-color": { - "version": "7.2.0", + "version": "9.4.0", + "resolved": "https://registry.npmjs.org/supports-color/-/supports-color-9.4.0.tgz", + "integrity": "sha512-VL+lNrEoIXww1coLPOmiEmK/0sGigko5COxI09KzHc2VJXJsQ37UaQ+8quuxjDeA7+KnLGTWRyOXSLLR2Wb4jw==", "dev": true, - "license": "MIT", - "dependencies": { - "has-flag": "^4.0.0" - }, "engines": { - "node": ">=8" + "node": ">=12" + }, + "funding": { + "url": "https://github.com/chalk/supports-color?sponsor=1" } }, "node_modules/supports-preserve-symlinks-flag": { diff --git a/package.json b/package.json index a12b8b498..7281d8671 100644 --- a/package.json +++ b/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", diff --git a/src/core-manager/index.js b/src/core-manager/index.js index 68c9a3261..60db08cfa 100644 --- a/src/core-manager/index.js +++ b/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,12 +128,12 @@ 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() @@ -141,7 +141,7 @@ export class CoreManager extends TypedEmitter { 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') }) diff --git a/src/index-writer/index.js b/src/index-writer/index.js index ae643b99f..54e0ea1c9 100644 --- a/src/index-writer/index.js +++ b/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', diff --git a/src/logger.js b/src/logger.js index 0e6d8b7cb..1c20667b2 100644 --- a/src/logger.js +++ b/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} args - */ - log = (...args) => { - this.#log.apply(this, args) + get log() { + return this.#log } /** * diff --git a/src/mapeo-manager.js b/src/mapeo-manager.js index 6e2cea6d7..6457c7cc7 100644 --- a/src/mapeo-manager.js +++ b/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 */ diff --git a/src/mapeo-project.js b/src/mapeo-project.js index dc92ba03b..ab574ae16 100644 --- a/src/mapeo-project.js +++ b/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) } } diff --git a/src/sync/peer-sync-controller.js b/src/sync/peer-sync-controller.js index 5f442f42f..7e9369776 100644 --- a/src/sync/peer-sync-controller.js +++ b/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} */ - async #unreplicateCore(core) { + async #unreplicateCoreRecord({ core, namespace }) { if (core === this.#coreManager.creatorCore) return this.#replicatingCores.delete(core) @@ -266,7 +284,7 @@ export class PeerSyncController { } unreplicate(core, this.#protomux) - this.#log('unreplicated core %k', core.key) + this.#log('unreplicated %s core %k', namespace, core.key) } /** @@ -274,8 +292,8 @@ export class PeerSyncController { */ #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) diff --git a/src/sync/sync-api.js b/src/sync/sync-api.js index bffa26863..57c2c5f92 100644 --- a/src/sync/sync-api.js +++ b/src/sync/sync-api.js @@ -261,7 +261,9 @@ export class SyncApi extends TypedEmitter { syncEnabledState = 'presync' } - this.#l.log(`Setting sync enabled state to "${syncEnabledState}"`) + if (syncEnabledState !== this.#previousSyncEnabledState) { + this.#l.log(`Setting sync enabled state to "${syncEnabledState}"`) + } for (const peerSyncController of this.#peerSyncControllers.values()) { peerSyncController.setSyncEnabledState(syncEnabledState) } @@ -435,7 +437,6 @@ export class SyncApi extends TypedEmitter { for (const result of ownershipResults) { if (result.status === 'rejected') continue await this.#validateRoleAndAddCoresForPeer(result.value) - this.#l.log('Added cores for device %S', result.value.docId) } } @@ -457,10 +458,8 @@ export class SyncApi extends TypedEmitter { coreOwnershipDocId ) await this.#validateRoleAndAddCoresForPeer(coreOwnershipDoc) - this.#l.log('Added cores for device %S', coreOwnershipDocId) } catch (_) { // Ignore, we'll add these when the role is added - this.#l.log('No role for device %S', coreOwnershipDocId) } })() ) @@ -485,6 +484,7 @@ export class SyncApi extends TypedEmitter { const coreKey = Buffer.from(coreOwnership[`${ns}CoreId`], 'hex') this.#coreManager.addCore(coreKey, ns) } + this.#l.log('Added non-auth cores for peer %S', peerDeviceId) } }