diff --git a/packages/client/test/sync/fetcher/storagefetcher.spec.ts b/packages/client/test/sync/fetcher/storagefetcher.spec.ts index cf7b8a561a..f0a199de96 100644 --- a/packages/client/test/sync/fetcher/storagefetcher.spec.ts +++ b/packages/client/test/sync/fetcher/storagefetcher.spec.ts @@ -1,8 +1,7 @@ import { RLP } from '@ethereumjs/rlp' import { hexToBytes } from '@ethereumjs/util' import { utf8ToBytes } from 'ethereum-cryptography/utils' -import * as td from 'testdouble' -import { assert, describe, it } from 'vitest' +import { assert, describe, it, vi } from 'vitest' import { Chain } from '../../../src/blockchain' import { Config } from '../../../src/config' @@ -14,13 +13,17 @@ import { _accountRangeRLP } from './accountfetcher.spec' const _storageRangesRLP = '0xf83e0bf83af838f7a0290decd9548b62a8d60345a988386fc84ba6bc95484008f6362f93160ef3e5639594053cd080a26cb03d5e6d2956cebb31c56e7660cac0' +;(BigInt.prototype as any).toJSON = function () { + return this.toString() +} + describe('[StorageFetcher]', async () => { class PeerPool { idle() {} ban() {} } - PeerPool.prototype.idle = td.func() - PeerPool.prototype.ban = td.func() + PeerPool.prototype.idle = vi.fn() + PeerPool.prototype.ban = vi.fn() const { StorageFetcher } = await import('../../../src/sync/fetcher/storagefetcher') @@ -271,11 +274,17 @@ describe('[StorageFetcher]', async () => { resData ) const { reqId, slots, proof } = res - const mockedGetStorageRanges = td.func() - td.when(mockedGetStorageRanges(td.matchers.anything())).thenReturn({ - reqId, - slots, - proof, + const mockedGetStorageRanges = vi.fn((input) => { + const expected = { + root: utf8ToBytes(''), + accounts: [ + hexToBytes('0x00009e5969eba9656d7e4dad5b0596241deb87c29bbab71c23b602c2b88a7276'), + ], + origin: hexToBytes('0x0000000000000000000000000000000000000000000000000000000000000000'), + limit: hexToBytes('0xffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff'), + bytes: BigInt(50000), + } + if (JSON.stringify(input) !== JSON.stringify(expected)) throw Error('input not as expected') }) const peer = { snap: { getStorageRanges: mockedGetStorageRanges }, @@ -284,17 +293,33 @@ describe('[StorageFetcher]', async () => { } const job = { peer, partialResult, task } await fetcher.request(job as any) - td.verify( - job.peer.snap.getStorageRanges({ - root: utf8ToBytes(''), - accounts: [ - hexToBytes('0x00009e5969eba9656d7e4dad5b0596241deb87c29bbab71c23b602c2b88a7276'), - ], - origin: td.matchers.anything(), - limit: td.matchers.anything(), - bytes: BigInt(50000), - }) + + peer.snap.getStorageRanges = vi.fn().mockReturnValueOnce({ + reqId, + slots: [], + proof: [new Uint8Array()], + }) + let ret = await fetcher.request(job as any) + assert.ok( + ret?.completed === true, + 'should handle peer that is signaling that an empty range has been requested with no elements remaining to the right' ) + + peer.snap.getStorageRanges = vi.fn().mockReturnValueOnce({ + reqId, + slots: slots + [new Uint8Array()], + proof, + }) + ret = await fetcher.request(job as any) + assert.notOk(ret, "Reject the response if the hash sets and slot sets don't match") + + peer.snap.getStorageRanges = vi.fn().mockReturnValueOnce({ + reqId, + slots: [], + proof: [], + }) + ret = await fetcher.request(job as any) + assert.notOk(ret, 'Should stop requesting from peer that rejected storage request') }) it('should verify proof correctly', async () => { @@ -334,8 +359,7 @@ describe('[StorageFetcher]', async () => { resData ) const { reqId, slots, proof } = res - const mockedGetStorageRanges = td.func() - td.when(mockedGetStorageRanges(td.matchers.anything())).thenReturn({ + const mockedGetStorageRanges = vi.fn().mockReturnValueOnce({ reqId, slots, proof, @@ -404,11 +428,7 @@ describe('[StorageFetcher]', async () => { first: BigInt(1), count: BigInt(10), }) - td.when((fetcher as any).pool.idle(td.matchers.anything())).thenReturn('peer0') + ;(fetcher as any).pool.idle = vi.fn(() => 'peer0') assert.equal(fetcher.peer(), 'peer0' as any, 'found peer') }) - - it('should reset td', () => { - td.reset() - }) }) diff --git a/packages/trie/README.md b/packages/trie/README.md index 1865368aa9..d9225e45fb 100644 --- a/packages/trie/README.md +++ b/packages/trie/README.md @@ -265,6 +265,62 @@ npm run profiling 0x processes the stacks and generates a profile folder (`.0x`) containing [`flamegraph.html`](https://github.com/davidmarkclements/0x/blob/master/docs/ui.md). +## Debugging + +The `Trie` class features optional debug logging.. Individual debug selections can be activated on the CL with `DEBUG=ethjs,[Logger Selection]`. + +`ethjs` **must** be included in the `DEBUG` environment variables to enable **any** logs. +Additional log selections can be added with a comma separated list (no spaces). Logs with extensions can be enabled with a colon `:`, and `*` can be used to include all extensions. + +`DEBUG=ethjs,thislog,thatlog,otherlog,otherlog:sublog,anotherLog:* node myscript.js` + +The following options are available: + +| Logger | Description | +| ----------------- | ---------------------------------------------- | +| `trie` | minimal info logging for all trie methods | +| `trie:` | debug logging for specific trie method | +| `trie::*` | verbose debug logging for specific trie method | +| `trie:*` | verbose debug logging for all trie methods | + +To observe the logging in action at different levels: + +Run with minimal logging: + +```shell +DEBUG=ethjs,trie npx vitest test/util/log.spec.ts +``` + +Run with **put** method logging: + +```shell +DEBUG=ethjs,trie:PUT npx vitest test/util/log.spec.ts +``` + +Run with **trie** + **put**/**get**/**del** logging: + +```shell +DEBUG=ethjs,trie,trie:PUT,trie:GET,trie:DEL npx vitest test/util/log.spec.ts +``` + +Run with **findPath** debug logging: + +```shell +DEBUG=ethjs,trie:FIND_PATH npx vitest test/util/log.spec.ts +``` + +Run with **findPath** verbose logging: + +```shell +DEBUG=ethjs,trie:FIND_PATH:* npx vitest test/util/log.spec.ts +``` + +Run with max logging: + +```shell +DEBUG=ethjs,trie:* npx vitest test/util/log.spec.ts +``` + ## References - Wiki diff --git a/packages/trie/examples/logDemo.ts b/packages/trie/examples/logDemo.ts new file mode 100644 index 0000000000..d6638490dc --- /dev/null +++ b/packages/trie/examples/logDemo.ts @@ -0,0 +1,31 @@ +import { utf8ToBytes } from 'ethereum-cryptography/utils' +import { Trie } from '../dist/cjs/index.js' +import { debug } from 'debug' + +debug.enable('*') + +const trie_entries: [string, string | null][] = [ + ['do', 'verb'], + ['ether', 'wookiedoo'], + ['horse', 'stallion'], + ['shaman', 'horse'], + ['doge', 'coin'], + ['ether', null], + ['dog', 'puppy'], + ['shaman', null], +] + +const main = async () => { + process.env.DEBUG = 'ethjs,*trie*' + const trie = new Trie({ + useRootPersistence: true, + }) + for (const [key, value] of trie_entries) { + await trie.put(utf8ToBytes(key), value === null ? Uint8Array.from([]) : utf8ToBytes(value)) + } + const proof = await trie.createProof(utf8ToBytes('doge')) + const valid = await trie.verifyProof(trie.root(), utf8ToBytes('doge'), proof) + console.log('valid', valid) +} + +main() diff --git a/packages/trie/src/trie.ts b/packages/trie/src/trie.ts index 3c77cb2062..c743ac7084 100644 --- a/packages/trie/src/trie.ts +++ b/packages/trie/src/trie.ts @@ -3,11 +3,13 @@ import { MapDB, RLP_EMPTY_STRING, ValueEncoding, + bytesToHex, bytesToUnprefixedHex, bytesToUtf8, equalsBytes, unprefixedHexToBytes, } from '@ethereumjs/util' +import debug from 'debug' import { keccak256 } from 'ethereum-cryptography/keccak.js' import { CheckpointDB } from './db/index.js' @@ -38,6 +40,7 @@ import type { } from './types.js' import type { OnFound } from './util/asyncWalk.js' import type { BatchDBOp, DB, PutBatch } from '@ethereumjs/util' +import type { Debugger } from 'debug' interface Path { node: TrieNode | null @@ -66,6 +69,11 @@ export class Trie { protected _lock = new Lock() protected _root: Uint8Array + /** Debug logging */ + protected DEBUG: boolean + protected _debug: Debugger = debug('trie') + protected debug: (...args: any) => void + /** * Creates a new trie. * @param opts Options for instantiating the trie @@ -77,6 +85,17 @@ export class Trie { this._opts = { ...this._opts, ...opts } } + this.DEBUG = process.env.DEBUG?.includes('ethjs') === true + this.debug = this.DEBUG + ? (message: string, namespaces: string[] = []) => { + let log = this._debug + for (const name of namespaces) { + log = log.extend(name) + } + log(message) + } + : (..._: any) => {} + this.database(opts?.db ?? new MapDB()) this.EMPTY_TRIE_ROOT = this.hash(RLP_EMPTY_STRING) @@ -86,6 +105,14 @@ export class Trie { if (opts?.root) { this.root(opts.root) } + this.DEBUG && + this.debug(`Trie created: + || Root: ${bytesToHex(this.root())} + || Secure: ${this._opts.useKeyHashing} + || Persistent: ${this._opts.useRootPersistence} + || Pruning: ${this._opts.useNodePruning} + || CacheSize: ${this._opts.cacheSize} + || ----------------`) } static async create(opts?: TrieOpts) { @@ -133,14 +160,13 @@ export class Trie { if (value === null) { value = this.EMPTY_TRIE_ROOT } - + this.DEBUG && this.debug(`Setting root to ${bytesToHex(value)}`) if (value.length !== this._hashLen) { throw new Error(`Invalid root length. Roots are ${this._hashLen} bytes`) } this._root = value } - return this._root } @@ -167,11 +193,13 @@ export class Trie { * @returns A Promise that resolves to `Uint8Array` if a value was found or `null` if no value was found. */ async get(key: Uint8Array, throwIfMissing = false): Promise { + this.DEBUG && this.debug(`Key: ${bytesToHex(key)}`, ['GET']) const { node, remaining } = await this.findPath(this.appliedKey(key), throwIfMissing) let value: Uint8Array | null = null if (node && remaining.length === 0) { value = node.value() } + this.DEBUG && this.debug(`Value: ${value === null ? 'null' : bytesToHex(value)}`, ['GET']) return value } @@ -187,6 +215,8 @@ export class Trie { value: Uint8Array | null, skipKeyTransform: boolean = false ): Promise { + this.DEBUG && this.debug(`Key: ${bytesToHex(key)}`, ['PUT']) + this.DEBUG && this.debug(`Value: ${value === null ? 'null' : bytesToHex(key)}`, ['PUT']) if (this._opts.useRootPersistence && equalsBytes(key, ROOT_DB_KEY) === true) { throw new Error(`Attempted to set '${bytesToUtf8(ROOT_DB_KEY)}' key but it is not allowed.`) } @@ -244,6 +274,7 @@ export class Trie { * @returns A Promise that resolves once value is deleted. */ async del(key: Uint8Array, skipKeyTransform: boolean = false): Promise { + this.DEBUG && this.debug(`Key: ${bytesToHex(key)}`, ['DEL']) await this._lock.acquire() const appliedKey = skipKeyTransform ? key : this.appliedKey(key) const { node, stack } = await this.findPath(appliedKey) @@ -284,6 +315,7 @@ export class Trie { async findPath(key: Uint8Array, throwIfMissing = false): Promise { const stack: TrieNode[] = [] const targetKey = bytesToNibbles(key) + this.DEBUG && this.debug(`Target (${targetKey.length}): [${targetKey}]`, ['FIND_PATH']) let result: Path | null = null const onFound: FoundNodeFunction = async (_, node, keyProgress, walkController) => { @@ -295,15 +327,43 @@ export class Trie { return } + this.DEBUG && + this.debug( + `${node.constructor.name} FOUND${'_nibbles' in node ? `: [${node._nibbles}]` : ''}`, + ['FIND_PATH', keyProgress.toString()] + ) + const keyRemainder = targetKey.slice(matchingNibbleLength(keyProgress, targetKey)) + this.DEBUG && this.debug(`[${keyRemainder}] Remaining`, ['FIND_PATH', keyProgress.toString()]) stack.push(node) + this.DEBUG && + this.debug( + `Adding ${node.constructor.name} to STACK (size: ${stack.length}) ${stack.map( + (e, i) => `${i === stack.length - 1 ? '\n|| +' : '\n|| '}` + e.constructor.name + )}`, + ['FIND_PATH'] + ) if (node instanceof BranchNode) { if (keyRemainder.length === 0) { result = { node, remaining: [], stack } } else { const branchIndex = keyRemainder[0] + this.DEBUG && + this.debug(`Looking for node on branch index: [${branchIndex}]`, [ + 'FIND_PATH', + 'BranchNode', + ]) const branchNode = node.getBranch(branchIndex) + this.DEBUG && + this.debug( + branchNode === null + ? 'NULL' + : branchNode instanceof Uint8Array + ? `NodeHash: ${bytesToHex(branchNode)}` + : `Raw_Node: ${branchNode.toString()}`, + ['FIND_PATH', 'BranchNode', branchIndex.toString()] + ) if (!branchNode) { result = { node: null, remaining: keyRemainder, stack } } else { @@ -317,16 +377,29 @@ export class Trie { result = { node: null, remaining: keyRemainder, stack } } } else if (node instanceof ExtensionNode) { + this.DEBUG && + this.debug( + `Comparing node key to expected\n|| Node_Key: [${node.key()}]\n|| Expected: [${keyRemainder.slice( + 0, + node.key().length + )}]\n|| Matching: [${ + keyRemainder.slice(0, node.key().length).toString() === node.key().toString() + }] + `, + ['FIND_PATH', 'ExtensionNode'] + ) const matchingLen = matchingNibbleLength(keyRemainder, node.key()) if (matchingLen !== node.key().length) { result = { node: null, remaining: keyRemainder, stack } } else { + this.DEBUG && this.debug(`NextNode: ${node.value()}`, ['FIND_PATH', 'ExtensionNode']) walkController.allChildren(node, keyProgress) } } } try { + this.DEBUG && this.debug(`Walking trie from root: ${bytesToHex(this.root())}`, ['FIND_PATH']) await this.walkTrie(this.root(), onFound) } catch (error: any) { if (error.message !== 'Missing node in DB' || throwIfMissing) { @@ -337,7 +410,23 @@ export class Trie { if (result === null) { result = { node: null, remaining: [], stack } } - + this.DEBUG && + this.debug( + result.node !== null + ? `Target Node FOUND for ${bytesToNibbles(key)}` + : `Target Node NOT FOUND`, + ['FIND_PATH'] + ) + + this.DEBUG && + this.debug( + `Result: \n|| Node: ${ + result.node === null ? 'null' : result.node.constructor.name + }\n|| Remaining: [${result.remaining}]\n|| Stack: ${result.stack + .map((e) => e.constructor.name) + .join(', ')}`, + ['FIND_PATH'] + ) return result } @@ -400,8 +489,11 @@ export class Trie { */ async lookupNode(node: Uint8Array | Uint8Array[]): Promise { if (isRawNode(node)) { - return decodeRawNode(node) + const decoded = decodeRawNode(node) + this.DEBUG && this.debug(`${decoded.constructor.name}`, ['LOOKUP_NODE', 'RAW_NODE']) + return decoded } + this.DEBUG && this.debug(`${`${bytesToHex(node)}`}`, ['LOOKUP_NODE', 'BY_HASH']) const value = (await this._db.get(node)) ?? null if (value === null) { @@ -409,7 +501,9 @@ export class Trie { throw new Error('Missing node in DB') } - return decodeNode(value) + const decoded = decodeNode(value) + this.DEBUG && this.debug(`${decoded.constructor.name} found in DB`, ['LOOKUP_NODE', 'BY_HASH']) + return decoded } /** @@ -762,6 +856,7 @@ export class Trie { * @param proof */ async fromProof(proof: Proof): Promise { + this.DEBUG && this.debug(`Saving (${proof.length}) proof nodes in DB`, ['FROM_PROOF']) const opStack = proof.map((nodeValue) => { return { type: 'put', @@ -775,6 +870,7 @@ export class Trie { opStack[0] !== undefined && opStack[0] !== null ) { + this.DEBUG && this.debug(`Setting Trie root from Proof Node 0`, ['FROM_PROOF']) this.root(opStack[0].key) } @@ -788,10 +884,12 @@ export class Trie { * @param key */ async createProof(key: Uint8Array): Promise { + this.DEBUG && this.debug(`Creating Proof for Key: ${bytesToHex(key)}`, ['CREATE_PROOF']) const { stack } = await this.findPath(this.appliedKey(key)) const p = stack.map((stackElem) => { return stackElem.serialize() }) + this.DEBUG && this.debug(`Proof created with (${stack.length}) nodes`, ['CREATE_PROOF']) return p } @@ -808,6 +906,14 @@ export class Trie { key: Uint8Array, proof: Proof ): Promise { + this.DEBUG && + this.debug( + `Verifying Proof:\n|| Key: ${bytesToHex(key)}\n|| Root: ${bytesToHex( + rootHash + )}\n|| Proof: (${proof.length}) nodes + `, + ['VERIFY_PROOF'] + ) const proofTrie = new Trie({ root: rootHash, useKeyHashingFunction: this._opts.useKeyHashingFunction, @@ -818,7 +924,12 @@ export class Trie { throw new Error('Invalid proof nodes given') } try { + this.DEBUG && + this.debug(`Verifying proof by retrieving key: ${bytesToHex(key)} from proof trie`, [ + 'VERIFY_PROOF', + ]) const value = await proofTrie.get(this.appliedKey(key), true) + this.DEBUG && this.debug(`PROOF VERIFIED`, ['VERIFY_PROOF']) return value } catch (err: any) { if (err.message === 'Missing node in DB') { @@ -943,6 +1054,13 @@ export class Trie { */ async persistRoot() { if (this._opts.useRootPersistence) { + this.DEBUG && + this.debug( + `Persisting root: \n|| RootHash: ${bytesToHex(this.root())}\n|| RootKey: ${bytesToHex( + this.appliedKey(ROOT_DB_KEY) + )}`, + ['PERSIST_ROOT'] + ) await this._db.put(this.appliedKey(ROOT_DB_KEY), this.root()) } } @@ -994,6 +1112,7 @@ export class Trie { * After this is called, all changes can be reverted until `commit` is called. */ checkpoint() { + this.DEBUG && this.debug(`${bytesToHex(this.root())}`, ['CHECKPOINT']) this._db.checkpoint(this.root()) } @@ -1006,7 +1125,7 @@ export class Trie { if (!this.hasCheckpoints()) { throw new Error('trying to commit when not checkpointed') } - + this.DEBUG && this.debug(`${bytesToHex(this.root())}`, ['COMMIT']) await this._lock.acquire() await this._db.commit() await this.persistRoot() @@ -1023,16 +1142,20 @@ export class Trie { throw new Error('trying to revert when not checkpointed') } + this.DEBUG && this.debug(`${bytesToHex(this.root())}`, ['REVERT', 'BEFORE']) await this._lock.acquire() this.root(await this._db.revert()) await this.persistRoot() this._lock.release() + this.DEBUG && this.debug(`${bytesToHex(this.root())}`, ['REVERT', 'AFTER']) } /** * Flushes all checkpoints, restoring the initial checkpoint state. */ flushCheckpoints() { + this.DEBUG && + this.debug(`Deleting ${this._db.checkpoints.length} checkpoints.`, ['FLUSH_CHECKPOINTS']) this._db.checkpoints = [] } } diff --git a/packages/trie/test/util/log.spec.ts b/packages/trie/test/util/log.spec.ts new file mode 100644 index 0000000000..a5c4b801f0 --- /dev/null +++ b/packages/trie/test/util/log.spec.ts @@ -0,0 +1,41 @@ +import { utf8ToBytes } from 'ethereum-cryptography/utils' +import { assert, describe, it } from 'vitest' + +import { Trie } from '../../src/trie.js' + +describe('Run Trie script with DEBUG enabled', async () => { + const trie_entries: [string, string | null][] = [ + ['do', 'verb'], + ['ether', 'wookiedoo'], + ['doge', 'coin'], + ['ether', null], + ['dog', 'puppy'], + ] + process.env.DEBUG = 'ethjs' + const trie = new Trie({ + useRootPersistence: true, + }) + for (const [key, value] of trie_entries) { + await trie.put(utf8ToBytes(key), value === null ? Uint8Array.from([]) : utf8ToBytes(value)) + } + + const proof = await trie.createProof(utf8ToBytes('doge')) + const valid = await trie.verifyProof(trie.root(), utf8ToBytes('doge'), proof) + + it('should be valid', async () => { + assert.deepEqual(valid, utf8ToBytes('coin')) + }) + + trie.checkpoint() + await trie.commit() + trie.flushCheckpoints() + trie.checkpoint() + await trie.revert() + process.env.DEBUG = '' + const trie2 = new Trie({}) + trie2['DEBUG'] = true + await trie2.fromProof(proof) + it('tries should share root', async () => { + assert.deepEqual(trie.root(), trie2.root()) + }) +})