From 9eaa5278766da48fd4a1eba4b9b03a49290df1b8 Mon Sep 17 00:00:00 2001 From: Santiago Palladino Date: Tue, 10 Dec 2024 18:53:11 -0300 Subject: [PATCH] chore: Tweak validator logs (#10597) Tweaks logs in the validator and a few on p2p. --- yarn-project/p2p/src/client/p2p_client.ts | 4 +- .../src/mem_pools/tx_pool/aztec_kv_tx_pool.ts | 2 +- .../src/mem_pools/tx_pool/memory_tx_pool.ts | 2 +- yarn-project/p2p/src/service/peer_manager.ts | 2 +- yarn-project/p2p/src/service/peer_scoring.ts | 4 +- .../p2p/src/service/reqresp/reqresp.ts | 6 +-- .../src/sequencer/sequencer.ts | 2 +- .../validator-client/src/validator.ts | 47 +++++++++++-------- 8 files changed, 40 insertions(+), 29 deletions(-) diff --git a/yarn-project/p2p/src/client/p2p_client.ts b/yarn-project/p2p/src/client/p2p_client.ts index 9884d4b4e3f..89a9853fe41 100644 --- a/yarn-project/p2p/src/client/p2p_client.ts +++ b/yarn-project/p2p/src/client/p2p_client.ts @@ -434,9 +434,11 @@ export class P2PClient extends WithTracer implements P2P { public async requestTxByHash(txHash: TxHash): Promise { const tx = await this.p2pService.sendRequest(TX_REQ_PROTOCOL, txHash); - this.log.debug(`Requested ${txHash.toString()} from peer | success = ${!!tx}`); if (tx) { + this.log.debug(`Received tx ${txHash.toString()} from peer`); await this.txPool.addTxs([tx]); + } else { + this.log.debug(`Failed to receive tx ${txHash.toString()} from peer`); } return tx; diff --git a/yarn-project/p2p/src/mem_pools/tx_pool/aztec_kv_tx_pool.ts b/yarn-project/p2p/src/mem_pools/tx_pool/aztec_kv_tx_pool.ts index 4cb2eaa3c18..70c858f08fb 100644 --- a/yarn-project/p2p/src/mem_pools/tx_pool/aztec_kv_tx_pool.ts +++ b/yarn-project/p2p/src/mem_pools/tx_pool/aztec_kv_tx_pool.ts @@ -125,7 +125,7 @@ export class AztecKVTxPool implements TxPool { let pendingCount = 0; for (const [i, tx] of txs.entries()) { const txHash = txHashes[i]; - this.#log.info(`Adding tx with id ${txHash.toString()}`, { + this.#log.verbose(`Adding tx ${txHash.toString()} to pool`, { eventName: 'tx-added-to-pool', ...tx.getStats(), } satisfies TxAddedToPoolStats); diff --git a/yarn-project/p2p/src/mem_pools/tx_pool/memory_tx_pool.ts b/yarn-project/p2p/src/mem_pools/tx_pool/memory_tx_pool.ts index 12619656ef4..c727ad07098 100644 --- a/yarn-project/p2p/src/mem_pools/tx_pool/memory_tx_pool.ts +++ b/yarn-project/p2p/src/mem_pools/tx_pool/memory_tx_pool.ts @@ -105,7 +105,7 @@ export class InMemoryTxPool implements TxPool { let pending = 0; for (const tx of txs) { const txHash = tx.getTxHash(); - this.log.debug(`Adding tx with id ${txHash.toString()}`, { + this.log.verbose(`Adding tx ${txHash.toString()} to pool`, { eventName: 'tx-added-to-pool', ...tx.getStats(), } satisfies TxAddedToPoolStats); diff --git a/yarn-project/p2p/src/service/peer_manager.ts b/yarn-project/p2p/src/service/peer_manager.ts index 7f12a4679bc..0a174d54258 100644 --- a/yarn-project/p2p/src/service/peer_manager.ts +++ b/yarn-project/p2p/src/service/peer_manager.ts @@ -221,7 +221,7 @@ export class PeerManager { const id = peer.peerId.toString(); await this.libP2PNode.peerStore.merge(peer.peerId, { multiaddrs: [peer.multiaddrTcp] }); - this.logger.debug(`Dialing peer ${id}`); + this.logger.trace(`Dialing peer ${id}`); try { await this.libP2PNode.dial(peer.multiaddrTcp); } catch (error) { diff --git a/yarn-project/p2p/src/service/peer_scoring.ts b/yarn-project/p2p/src/service/peer_scoring.ts index 896eb0a69b6..abf407798e1 100644 --- a/yarn-project/p2p/src/service/peer_scoring.ts +++ b/yarn-project/p2p/src/service/peer_scoring.ts @@ -82,7 +82,7 @@ export class PeerScoring { return this.scores.get(peerId) || 0; } - getStats(): { median: number } { - return { median: median(Array.from(this.scores.values())) ?? 0 }; + getStats(): { medianScore: number } { + return { medianScore: median(Array.from(this.scores.values())) ?? 0 }; } } diff --git a/yarn-project/p2p/src/service/reqresp/reqresp.ts b/yarn-project/p2p/src/service/reqresp/reqresp.ts index 86aea3ee781..e6794c6fecf 100644 --- a/yarn-project/p2p/src/service/reqresp/reqresp.ts +++ b/yarn-project/p2p/src/service/reqresp/reqresp.ts @@ -196,7 +196,7 @@ export class ReqResp { let stream: Stream | undefined; try { stream = await this.libp2p.dialProtocol(peerId, subProtocol); - this.logger.debug(`Stream opened with ${peerId.toString()} for ${subProtocol}`); + this.logger.trace(`Stream opened with ${peerId.toString()} for ${subProtocol}`); // Open the stream with a timeout const result = await executeTimeoutWithCustomError( @@ -206,7 +206,7 @@ export class ReqResp { ); await stream.close(); - this.logger.debug(`Stream closed with ${peerId.toString()} for ${subProtocol}`); + this.logger.trace(`Stream closed with ${peerId.toString()} for ${subProtocol}`); return result; } catch (e: any) { @@ -216,7 +216,7 @@ export class ReqResp { if (stream) { try { await stream.close(); - this.logger.debug(`Stream closed with ${peerId.toString()} for ${subProtocol}`); + this.logger.trace(`Stream closed with ${peerId.toString()} for ${subProtocol}`); } catch (closeError) { this.logger.error( `Error closing stream: ${closeError instanceof Error ? closeError.message : 'Unknown error'}`, diff --git a/yarn-project/sequencer-client/src/sequencer/sequencer.ts b/yarn-project/sequencer-client/src/sequencer/sequencer.ts index f1df58e18b0..f868980cf5e 100644 --- a/yarn-project/sequencer-client/src/sequencer/sequencer.ts +++ b/yarn-project/sequencer-client/src/sequencer/sequencer.ts @@ -713,7 +713,7 @@ export class Sequencer { this.log.debug('Creating block proposal'); const proposal = await this.validatorClient.createBlockProposal(block.header, block.archive.root, txHashes); if (!proposal) { - this.log.verbose(`Failed to create block proposal, skipping`); + this.log.verbose(`Failed to create block proposal, skipping collecting attestations`); return undefined; } diff --git a/yarn-project/validator-client/src/validator.ts b/yarn-project/validator-client/src/validator.ts index 84bed8fdc49..179b7307294 100644 --- a/yarn-project/validator-client/src/validator.ts +++ b/yarn-project/validator-client/src/validator.ts @@ -127,6 +127,16 @@ export class ValidatorClient extends WithTracer implements Validator { } async attestToProposal(proposal: BlockProposal): Promise { + const slotNumber = proposal.slotNumber.toNumber(); + const proposalInfo = { + slotNumber, + blockNumber: proposal.payload.header.globalVariables.blockNumber.toNumber(), + archive: proposal.payload.archive.toString(), + txCount: proposal.payload.txHashes.length, + txHashes: proposal.payload.txHashes.map(txHash => txHash.toString()), + }; + this.log.verbose(`Received request to attest for slot ${slotNumber}`); + // Check that I am in the committee if (!(await this.epochCache.isInCommittee(this.keyStore.getAddress()))) { this.log.verbose(`Not in the committee, skipping attestation`); @@ -150,10 +160,7 @@ export class ValidatorClient extends WithTracer implements Validator { } // Check that all of the tranasctions in the proposal are available in the tx pool before attesting - this.log.verbose(`request to attest`, { - archive: proposal.payload.archive.toString(), - txHashes: proposal.payload.txHashes.map(txHash => txHash.toString()), - }); + this.log.verbose(`Processing attestation for slot ${slotNumber}`, proposalInfo); try { await this.ensureTransactionsAreAvailable(proposal); @@ -164,19 +171,17 @@ export class ValidatorClient extends WithTracer implements Validator { } catch (error: any) { // If the transactions are not available, then we should not attempt to attest if (error instanceof TransactionsNotAvailableError) { - this.log.error(`Transactions not available, skipping attestation ${error.message}`); + this.log.error(`Transactions not available, skipping attestation`, error, proposalInfo); } else { // This branch most commonly be hit if the transactions are available, but the re-execution fails // Catch all error handler - this.log.error(`Failed to attest to proposal: ${error.message}`); + this.log.error(`Failed to attest to proposal`, error, proposalInfo); } return undefined; } // Provided all of the above checks pass, we can attest to the proposal - this.log.verbose( - `Transactions available, attesting to proposal with ${proposal.payload.txHashes.length} transactions`, - ); + this.log.info(`Attesting to proposal for slot ${slotNumber}`, proposalInfo); // If the above function does not throw an error, then we can attest to the proposal return this.validationService.attestToProposal(proposal); @@ -195,7 +200,6 @@ export class ValidatorClient extends WithTracer implements Validator { // If we cannot request all of the transactions, then we should fail if (txs.length !== txHashes.length) { - this.log.error(`Failed to get transactions from the network: ${txHashes.join(', ')}`); throw new TransactionsNotAvailableError(txHashes); } @@ -209,7 +213,7 @@ export class ValidatorClient extends WithTracer implements Validator { const { block } = await this.blockBuilder(txs, header.globalVariables); stopTimer(); - this.log.verbose(`Re-ex: Re-execution complete`); + this.log.verbose(`Transaction re-execution complete`); // This function will throw an error if state updates do not match if (!block.archive.root.equals(proposal.archive)) { @@ -240,7 +244,6 @@ export class ValidatorClient extends WithTracer implements Validator { const requestedTxs = await this.p2pClient.requestTxs(missingTxs); if (requestedTxs.some(tx => tx === undefined)) { - this.log.error(`Failed to request transactions from the network: ${missingTxs.join(', ')}`); throw new TransactionsNotAvailableError(missingTxs); } } @@ -267,30 +270,36 @@ export class ValidatorClient extends WithTracer implements Validator { ): Promise { // Wait and poll the p2pClient's attestation pool for this block until we have enough attestations const slot = proposal.payload.header.globalVariables.slotNumber.toBigInt(); - this.log.info(`Waiting for ${numberOfRequiredAttestations} attestations for slot: ${slot}`); + this.log.debug(`Collecting ${numberOfRequiredAttestations} attestations for slot ${slot}`); const proposalId = proposal.archive.toString(); const myAttestation = await this.validationService.attestToProposal(proposal); const startTime = Date.now(); + let attestations: BlockAttestation[] = []; while (true) { - const attestations = [myAttestation, ...(await this.p2pClient.getAttestationsForSlot(slot, proposalId))]; + const collectedAttestations = [myAttestation, ...(await this.p2pClient.getAttestationsForSlot(slot, proposalId))]; + const newAttestations = collectedAttestations.filter( + collected => !attestations.some(old => old.getSender().equals(collected.getSender())), + ); + for (const attestation of newAttestations) { + this.log.debug(`Received attestation for slot ${slot} from ${attestation.getSender().toString()}`); + } + attestations = collectedAttestations; if (attestations.length >= numberOfRequiredAttestations) { - this.log.info(`Collected all ${numberOfRequiredAttestations} attestations for slot, ${slot}`); + this.log.verbose(`Collected all ${numberOfRequiredAttestations} attestations for slot ${slot}`); return attestations; } const elapsedTime = Date.now() - startTime; if (elapsedTime > this.config.attestationWaitTimeoutMs) { - this.log.error(`Timeout waiting for ${numberOfRequiredAttestations} attestations for slot, ${slot}`); + this.log.error(`Timeout waiting for ${numberOfRequiredAttestations} attestations for slot ${slot}`); throw new AttestationTimeoutError(numberOfRequiredAttestations, slot); } - this.log.verbose( - `Collected ${attestations.length} attestations so far, waiting ${this.config.attestationPollingIntervalMs}ms for more...`, - ); + this.log.debug(`Collected ${attestations.length} attestations so far`); await sleep(this.config.attestationPollingIntervalMs); } }