Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Debug logger namespace standardization #3692

Merged
merged 30 commits into from
Sep 25, 2024
Merged
Show file tree
Hide file tree
Changes from 19 commits
Commits
Show all changes
30 commits
Select commit Hold shift + click to select a range
f7eff49
trie: Make debug logger tags use lower case naming
scorbajio Sep 20, 2024
77e1a35
verkle: Make debug logger tags use lower case naming
scorbajio Sep 20, 2024
82db3fa
trie: Update debug namespaces in README
scorbajio Sep 20, 2024
515c744
trie: Update debug examples to use lower case naming
scorbajio Sep 20, 2024
6bc8bc8
verkle: Update debug namespaces in README
scorbajio Sep 20, 2024
69eb81e
verkle: Update debug examples in README to use lower case naming
scorbajio Sep 20, 2024
79f6c2a
trie: Print hex instead of bytes to console
scorbajio Sep 20, 2024
c8f0032
Change root debug namespaces to include a collon-hash to be included …
scorbajio Sep 20, 2024
7b23b79
Make base namespace end with colon-hash in docs and READMEs
scorbajio Sep 20, 2024
5a3764b
Do not calculate canoncial header if DEBUG is not set
scorbajio Sep 20, 2024
a55b191
Fix spelling issue
scorbajio Sep 20, 2024
2cea049
Fix spelling mistakes
scorbajio Sep 20, 2024
4eb70fb
Make fetcher namespace use collon-pound
scorbajio Sep 23, 2024
41d5bd4
Remove unnecessary check
scorbajio Sep 23, 2024
07e99f0
Add verkle core namespace option to README
scorbajio Sep 23, 2024
8faf6f5
Update debug option description
scorbajio Sep 23, 2024
daceafd
Fix spelling mistake in example
scorbajio Sep 23, 2024
c704c9a
Merge branch 'master' into debug-namespace-standardization
scorbajio Sep 23, 2024
947e956
Merge branch 'master' into debug-namespace-standardization
holgerd77 Sep 24, 2024
1f11e6c
Update trie README debug namespaces
scorbajio Sep 24, 2024
ac48007
Add proof symbols to debug options list
scorbajio Sep 24, 2024
1f7484e
Make proof-related debug tags lowercase
scorbajio Sep 24, 2024
91aa30a
Put branch index in debug message and out of namespace
scorbajio Sep 24, 2024
f924528
Merge branch 'debug-namespace-standardization' of github.com:ethereum…
scorbajio Sep 24, 2024
c939c73
Update verkle README debug namespaces
scorbajio Sep 24, 2024
ef402b4
Convert bytes before logging them
scorbajio Sep 24, 2024
b5670dd
Expand debug string logic and add branch index to it
scorbajio Sep 24, 2024
21916c8
Merge branch 'master' into debug-namespace-standardization
acolytec3 Sep 24, 2024
ec6471c
Do not convert bytes to hex
scorbajio Sep 25, 2024
ea2ae8d
Merge branch 'master' into debug-namespace-standardization
scorbajio Sep 25, 2024
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
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()
acolytec3 marked this conversation as resolved.
Show resolved Hide resolved
}
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 ${canonicalHeadHash} to ${bytesToHex(hash!)} (number ${bigIntToHex(canonicalHead)})`,
scorbajio marked this conversation as resolved.
Show resolved Hide resolved
)

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
34 changes: 23 additions & 11 deletions packages/trie/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -341,12 +341,24 @@ 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 |

To observe the logging in action at different levels:

Expand All @@ -359,25 +371,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 +401,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
49 changes: 25 additions & 24 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,8 +343,8 @@ 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 &&
Expand All @@ -354,7 +354,7 @@ export class Trie {
: branchNode instanceof Uint8Array
? `NodeHash: ${bytesToHex(branchNode)}`
: `Raw_Node: ${branchNode.toString()}`,
['FIND_PATH', 'BranchNode', branchIndex.toString()],
['find_path', 'branch_node', branchIndex.toString()],
)
if (!branchNode) {
result = { node: null, remaining: targetKey.slice(progress), stack }
Expand Down Expand Up @@ -388,11 +388,12 @@ 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: ${bytesToHex(node.value())}`, ['find_path', 'extension_node'])
if (k !== targetKey[progress]) {
result = { node: null, remaining: targetKey.slice(_progress), stack }
return
Expand All @@ -408,7 +409,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 +426,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 +437,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 +504,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 +517,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 +966,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 +1021,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 +1034,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 +1051,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
20 changes: 11 additions & 9 deletions packages/verkle/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -88,12 +88,14 @@ The `Verkle` class features optional debug logging. Individual debug selections

The following options are available:

| Logger | Description |
| ------------------- | ------------------------------------------------ |
| `verkle` | minimal info logging for all verkle methods |
| `verkle:<METHOD>` | debug logging for specific verkle method |
| `verkle:<METHOD>:*` | verbose debug logging for specific verkle method |
| `verkle:*` | verbose debug logging for all verkle methods |
| Logger | Description |
| ------------------- | ------------------------------------ |
| `verkle:#` | a core verkle operation has occurred |
| `verkle:put` | a verkle put operation has occurred |
scorbajio marked this conversation as resolved.
Show resolved Hide resolved
| `verkle:get` | a verkle get operation has occurred |
| `verkle:del` | a verkle del operation has occurred |
| `verkle:find_path` | a node is being searched for |
| `verkle:initialize` | a verkle object has been initialized |

To observe the logging in action at different levels:

Expand All @@ -106,13 +108,13 @@ DEBUG=ethjs,verkle npx vitest test/verkle.spec.ts
Run with **put** method logging:

```shell
DEBUG=ethjs,verkle:PUT npx vitest test/verkle.spec.ts
DEBUG=ethjs,verkle:put npx vitest test/verkle.spec.ts
```

Run with **verkle** + **put**/**get**/**del** logging:

```shell
DEBUG=ethjs,verkle,verkle:PUT,verkle:GET,verkle:DEL npx vitest test/verkle.spec.ts
DEBUG=ethjs,verkle,verkle:put,verkle:get,verkle:del npx vitest test/verkle.spec.ts
```

Run with max logging:
Expand All @@ -124,7 +126,7 @@ DEBUG=ethjs,verkle:* npx vitest test/verkle.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,tie:put,trie:find_path:* npx vitest test/proof.spec.ts`

## References

Expand Down
Loading
Loading