Skip to content

Commit

Permalink
Debug logger namespace standardization (#3692)
Browse files Browse the repository at this point in the history
* trie: Make debug logger tags use lower case naming

* verkle: Make debug logger tags use lower case naming

* trie: Update debug namespaces in README

* trie: Update debug examples to use lower case naming

* verkle: Update debug namespaces in README

* verkle: Update debug examples in README to use lower case naming

* trie: Print hex instead of bytes to console

* Change root debug namespaces to include a collon-hash to be included in wild-card namespaces

* Make base namespace end with colon-hash in docs and READMEs

* Do not calculate canoncial header if DEBUG is not set

* Fix spelling issue

* Fix spelling mistakes

* Make fetcher namespace use collon-pound

* Remove unnecessary check

* Add verkle core namespace option to README

* Update debug option description

* Fix spelling mistake in example

* Update trie README debug namespaces

* Add proof symbols to debug options list

* Make proof-related debug tags lowercase

* Put branch index in debug message and out of namespace

* Update verkle README debug namespaces

* Convert bytes before logging them

* Expand debug string logic and add branch index to it

* Do not convert bytes to hex

---------

Co-authored-by: Holger Drewes <[email protected]>
Co-authored-by: acolytec3 <[email protected]>
  • Loading branch information
3 people authored Sep 25, 2024
1 parent 15f8ff2 commit 58e68b9
Show file tree
Hide file tree
Showing 11 changed files with 107 additions and 82 deletions.
2 changes: 1 addition & 1 deletion packages/blockchain/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -247,7 +247,7 @@ The following initial logger is currently available:

| Logger | Description |
| ------------------- | ------------------------------------------------------------------------ |
| `blockchain` | Core blockchain operations like when a block or header is put or deleted |
| `blockchain:#` | Core blockchain operations like when a block or header is put or deleted |
| `blockchain:clique` | Clique consensus operations like updating the vote and/or signer list |
| `blockchain:ethash` | Ethash consensus operations like PoW block or header validation |

Expand Down
9 changes: 6 additions & 3 deletions packages/blockchain/src/blockchain.ts
Original file line number Diff line number Diff line change
Expand Up @@ -107,7 +107,7 @@ export class Blockchain implements BlockchainInterface {
constructor(opts: BlockchainOptions = {}) {
this.DEBUG =
typeof window === 'undefined' ? (process?.env?.DEBUG?.includes('ethjs') ?? false) : false
this._debug = debugDefault('blockchain')
this._debug = debugDefault('blockchain:#')

if (opts.common) {
this.common = opts.common
Expand Down Expand Up @@ -327,7 +327,10 @@ export class Blockchain implements BlockchainInterface {

async resetCanonicalHead(canonicalHead: bigint) {
let hash: Uint8Array | undefined
const canonicalHeadHash = (await this.getCanonicalHeadHeader()).hash()
let canonicalHeadHash: Uint8Array | undefined
if (this.DEBUG) {
canonicalHeadHash = (await this.getCanonicalHeadHeader()).hash()
}
await this.runWithLock<void>(async () => {
hash = await this.dbManager.numberToHash(canonicalHead)
if (hash === undefined) {
Expand All @@ -352,7 +355,7 @@ export class Blockchain implements BlockchainInterface {

this.DEBUG &&
this._debug(
`Canonical head set from ${bytesToHex(canonicalHeadHash)} to ${bytesToHex(hash!)} (number ${bigIntToHex(canonicalHead)})`,
`Canonical head set from ${bytesToHex(canonicalHeadHash!)} to ${bytesToHex(hash!)} (number ${bigIntToHex(canonicalHead)})`,
)

this._deletedBlocks = []
Expand Down
2 changes: 1 addition & 1 deletion packages/blockchain/src/constructors.ts
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,7 @@ import type { Chain } from '@ethereumjs/common'

const DEBUG =
typeof window === 'undefined' ? (process?.env?.DEBUG?.includes('ethjs') ?? false) : false
const debug = debugDefault('blockchain')
const debug = debugDefault('blockchain:#')

export async function createBlockchain(opts: BlockchainOptions = {}) {
const blockchain = new Blockchain(opts)
Expand Down
2 changes: 1 addition & 1 deletion packages/client/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -466,7 +466,7 @@ The following options are available:
| Logger | Description |
| ------------------- | ------------------------------------------------ |
| `client:fetcher` | This option enables logging for all fetchers |
| `client:fetcher:#` | This option enables logging for core fetcher operations such as job scheduling |
| `client:fetcher:bytecode` | This option enables logging for the snap sync bytecode fetcher |
| `client:fetcher:storage` | This option enables logging for the snap sync storage fetcher |
| `client:fetcher:trienode` | This option enables logging for the snap sync trienode fetcher |
Expand Down
2 changes: 1 addition & 1 deletion packages/client/src/sync/fetcher/fetcher.ts
Original file line number Diff line number Diff line change
Expand Up @@ -82,7 +82,7 @@ export abstract class Fetcher<JobTask, JobResult, StorageItem> extends Readable
typeof window === 'undefined' ? (process?.env?.DEBUG?.includes('ethjs') ?? false) : false

this.config = options.config
this.debug = debug('client:fetcher')
this.debug = debug('client:fetcher:#')

this.pool = options.pool
this.timeout = options.timeout ?? 8000
Expand Down
2 changes: 1 addition & 1 deletion packages/devp2p/src/util.ts
Original file line number Diff line number Diff line change
Expand Up @@ -7,7 +7,7 @@ import { secp256k1 } from 'ethereum-cryptography/secp256k1.js'
import type { ETH } from './protocol/eth.js'
import type { LES } from './protocol/les.js'

export const devp2pDebug = debug('devp2p')
export const devp2pDebug = debug('devp2p:#')

export function genPrivateKey(): Uint8Array {
const privateKey = secp256k1.utils.randomPrivateKey()
Expand Down
36 changes: 25 additions & 11 deletions packages/trie/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -341,12 +341,26 @@ The `Trie` class features optional debug logging. Individual debug selections ca

The following options are available:

| Logger | Description |
| ----------------- | ---------------------------------------------- |
| `trie` | minimal info logging for all trie methods |
| `trie:<METHOD>` | debug logging for specific trie method |
| `trie:<METHOD>:*` | verbose debug logging for specific trie method |
| `trie:*` | verbose debug logging for all trie methods |
| Logger | Description |
| --------------------------------- | -------------------------------------------------------------------- |
| `trie:#` | minimal info logging for all trie methods |
| `trie:#:put` | a trie put operation has occurred |
| `trie:#:get` | a trie get operation has occurred |
| `trie:#:del` | a trie del operation has occurred |
| `trie:#:find_path` | a node is being searched for |
| `trie:#:find_path:branch_node` | a branch node has been found during a node search |
| `trie:#:find_path:extension_node` | an extension node has been found during a node search |
| `trie:#:lookup_node` | node lookup operations |
| `trie:#:lookup_node:raw_node` | node lookup operations that have hit a raw node |
| `trie:#:lookup_node:by_hash` | node lookup operations that have hit a node hash |
| `trie:#:persist_root` | operations writing the state root to the disk |
| `trie:#:checkpoint` | checkpoint operations |
| `trie:#:commit` | operations committing checkpoints to the disk |
| `trie:#:revert:before` | the stateRoot before reverting committed checkpoints |
| `trie:#:revert:after` | the stateRoot after reverting committed checkpoints |
| `trie:#:flush_checkpoints` | checkpoints are being flushed |
| `trie:#:from_proof` | a trie has been updated from a proof using updateTrieFromMerkleProof |
| `trie:#:create_proof` | a merkle proof has been created using updateTrieFromMerkleProof |

To observe the logging in action at different levels:

Expand All @@ -359,25 +373,25 @@ 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
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
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
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
DEBUG=ethjs,trie:find_path:* npx vitest test/util/log.spec.ts
```

Run with max logging:
Expand All @@ -389,7 +403,7 @@ DEBUG=ethjs,trie:* npx vitest test/util/log.spec.ts
`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,tie:PUT,trie:FIND_PATH:* npx vitest test/proof.spec.ts`
`DEBUG=ethjs,trie:put,trie:find_path:* npx vitest test/proof.spec.ts`

## References

Expand Down
6 changes: 3 additions & 3 deletions packages/trie/src/proof/index.ts
Original file line number Diff line number Diff line change
Expand Up @@ -72,12 +72,12 @@ export function verifyTrieRangeProof(
* @param key key to create a proof for
*/
export async function createMerkleProof(trie: Trie, key: Uint8Array): Promise<Proof> {
trie['DEBUG'] && trie['debug'](`Creating Proof for Key: ${bytesToHex(key)}`, ['CREATE_PROOF'])
trie['DEBUG'] && trie['debug'](`Creating Proof for Key: ${bytesToHex(key)}`, ['create_proof'])
const { stack } = await trie.findPath(trie['appliedKey'](key))
const p = stack.map((stackElem) => {
return stackElem.serialize()
})
trie['DEBUG'] && trie['debug'](`Proof created with (${stack.length}) nodes`, ['CREATE_PROOF'])
trie['DEBUG'] && trie['debug'](`Proof created with (${stack.length}) nodes`, ['create_proof'])
return p
}

Expand All @@ -94,7 +94,7 @@ export async function updateTrieFromMerkleProof(
proof: Proof,
shouldVerifyRoot: boolean = false,
) {
trie['DEBUG'] && trie['debug'](`Saving (${proof.length}) proof nodes in DB`, ['FROM_PROOF'])
trie['DEBUG'] && trie['debug'](`Saving (${proof.length}) proof nodes in DB`, ['from_proof'])
const opStack = proof.map((nodeValue) => {
let key = Uint8Array.from(trie['hash'](nodeValue))
key = trie['_opts'].keyPrefix ? concatBytes(trie['_opts'].keyPrefix, key) : key
Expand Down
68 changes: 37 additions & 31 deletions packages/trie/src/trie.ts
Original file line number Diff line number Diff line change
Expand Up @@ -72,7 +72,7 @@ export class Trie {

/** Debug logging */
protected DEBUG: boolean
protected _debug: Debugger = debug('trie')
protected _debug: Debugger = debug('trie:#')
protected debug: (...args: any) => void

/**
Expand Down Expand Up @@ -187,13 +187,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<Uint8Array | null> {
this.DEBUG && this.debug(`Key: ${bytesToHex(key)}`, ['GET'])
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'])
this.DEBUG && this.debug(`Value: ${value === null ? 'null' : bytesToHex(value)}`, ['get'])
return value
}

Expand All @@ -209,8 +209,8 @@ export class Trie {
value: Uint8Array | null,
skipKeyTransform: boolean = false,
): Promise<void> {
this.DEBUG && this.debug(`Key: ${bytesToHex(key)}`, ['PUT'])
this.DEBUG && this.debug(`Value: ${value === null ? 'null' : bytesToHex(key)}`, ['PUT'])
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.`)
}
Expand Down Expand Up @@ -272,7 +272,7 @@ export class Trie {
* @returns A Promise that resolves once value is deleted.
*/
async del(key: Uint8Array, skipKeyTransform: boolean = false): Promise<void> {
this.DEBUG && this.debug(`Key: ${bytesToHex(key)}`, ['DEL'])
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)
Expand Down Expand Up @@ -331,7 +331,7 @@ export class Trie {
stack[i] = partialPath.stack[i]
progress += stack[i] instanceof BranchNode ? 1 : (<ExtensionNode>stack[i]).keyLength()
}
this.DEBUG && this.debug(`Target (${targetKey.length}): [${targetKey}]`, ['FIND_PATH'])
this.DEBUG && this.debug(`Target (${targetKey.length}): [${targetKey}]`, ['find_path'])
let result: Path | null = null

const onFound: FoundNodeFunction = async (_, node, keyProgress, walkController) => {
Expand All @@ -343,19 +343,25 @@ export class Trie {
const branchIndex = targetKey[progress]
this.DEBUG &&
this.debug(`Looking for node on branch index: [${branchIndex}]`, [
'FIND_PATH',
'BranchNode',
'find_path',
'branch_node',
])
const branchNode = node.getBranch(branchIndex)
this.DEBUG &&
this.debug(
branchNode === null
? 'NULL'
: branchNode instanceof Uint8Array

if (this.DEBUG) {
let debugString: string
if (branchNode === null) {
debugString = 'NULL'
} else {
debugString = `Branch index: ${branchIndex.toString()} - `
debugString +=
branchNode instanceof Uint8Array
? `NodeHash: ${bytesToHex(branchNode)}`
: `Raw_Node: ${branchNode.toString()}`,
['FIND_PATH', 'BranchNode', branchIndex.toString()],
)
: `Raw_Node: ${branchNode!.toString()}`
}

this.debug(debugString, ['find_path', 'branch_node'])
}
if (!branchNode) {
result = { node: null, remaining: targetKey.slice(progress), stack }
} else {
Expand Down Expand Up @@ -388,11 +394,11 @@ export class Trie {
node.key().toString()
}]
`,
['FIND_PATH', 'ExtensionNode'],
['find_path', 'extension_node'],
)
const _progress = progress
for (const k of node.key()) {
this.DEBUG && this.debug(`NextNode: ${node.value()}`, ['FIND_PATH', 'ExtensionNode'])
this.DEBUG && this.debug(`NextNode: ${node.value()}`, ['find_path', 'extension_node'])
if (k !== targetKey[progress]) {
result = { node: null, remaining: targetKey.slice(_progress), stack }
return
Expand All @@ -408,7 +414,7 @@ export class Trie {
this.DEBUG &&
this.debug(
`Walking trie from ${startingNode === undefined ? 'ROOT' : 'NODE'}: ${bytesToHex(start)}`,
['FIND_PATH'],
['find_path'],
)
await this.walkTrie(start, onFound)
} catch (error: any) {
Expand All @@ -425,7 +431,7 @@ export class Trie {
result.node !== null
? `Target Node FOUND for ${bytesToNibbles(key)}`
: `Target Node NOT FOUND`,
['FIND_PATH'],
['find_path'],
)

result.stack = result.stack.filter((e) => e !== undefined)
Expand All @@ -436,7 +442,7 @@ export class Trie {
|| Remaining: [${result.remaining}]\n|| Stack: ${result.stack
.map((e) => e.constructor.name)
.join(', ')}`,
['FIND_PATH'],
['find_path'],
)
return result
}
Expand Down Expand Up @@ -503,10 +509,10 @@ export class Trie {
async lookupNode(node: Uint8Array | Uint8Array[]): Promise<TrieNode> {
if (isRawNode(node)) {
const decoded = decodeRawNode(node)
this.DEBUG && this.debug(`${decoded.constructor.name}`, ['LOOKUP_NODE', 'RAW_NODE'])
this.DEBUG && this.debug(`${decoded.constructor.name}`, ['lookup_node', 'raw_node'])
return decoded
}
this.DEBUG && this.debug(`${`${bytesToHex(node)}`}`, ['LOOKUP_NODE', 'BY_HASH'])
this.DEBUG && this.debug(`${`${bytesToHex(node)}`}`, ['lookup_node', 'by_hash'])
const key = this._opts.keyPrefix ? concatBytes(this._opts.keyPrefix, node) : node
const value = (await this._db.get(key)) ?? null

Expand All @@ -516,7 +522,7 @@ export class Trie {
}

const decoded = decodeNode(value)
this.DEBUG && this.debug(`${decoded.constructor.name} found in DB`, ['LOOKUP_NODE', 'BY_HASH'])
this.DEBUG && this.debug(`${decoded.constructor.name} found in DB`, ['lookup_node', 'by_hash'])
return decoded
}

Expand Down Expand Up @@ -965,7 +971,7 @@ export class Trie {
`Persisting root: \n|| RootHash: ${bytesToHex(this.root())}\n|| RootKey: ${bytesToHex(
this.appliedKey(ROOT_DB_KEY),
)}`,
['PERSIST_ROOT'],
['persist_root'],
)
let key = this.appliedKey(ROOT_DB_KEY)
key = this._opts.keyPrefix ? concatBytes(this._opts.keyPrefix, key) : key
Expand Down Expand Up @@ -1020,7 +1026,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.DEBUG && this.debug(`${bytesToHex(this.root())}`, ['checkpoint'])
this._db.checkpoint(this.root())
}

Expand All @@ -1033,7 +1039,7 @@ export class Trie {
if (!this.hasCheckpoints()) {
throw new Error('trying to commit when not checkpointed')
}
this.DEBUG && this.debug(`${bytesToHex(this.root())}`, ['COMMIT'])
this.DEBUG && this.debug(`${bytesToHex(this.root())}`, ['commit'])
await this._lock.acquire()
await this._db.commit()
await this.persistRoot()
Expand All @@ -1050,20 +1056,20 @@ export class Trie {
throw new Error('trying to revert when not checkpointed')
}

this.DEBUG && this.debug(`${bytesToHex(this.root())}`, ['REVERT', 'BEFORE'])
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'])
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.debug(`Deleting ${this._db.checkpoints.length} checkpoints.`, ['flush_checkpoints'])
this._db.checkpoints = []
}

Expand Down
Loading

0 comments on commit 58e68b9

Please sign in to comment.