From 2fdf5ec903cbeee168fe02640061525c928185e8 Mon Sep 17 00:00:00 2001 From: municorn Date: Wed, 5 Jun 2024 20:30:27 -0600 Subject: [PATCH] feat: use `logFlags.seqdiagram` for all uses of `seqLogger` feat(logger): never set `seqdiagram` to true by default feat: add use_seqdiagram_logs.patch --- src/logger/index.ts | 5 --- src/p2p/Comms.ts | 28 ++++++------- src/rate-limiting/index.ts | 7 ++-- src/shardus/index.ts | 26 ++++++------ src/state-manager/TransactionConsensus.ts | 32 +++++++-------- src/state-manager/TransactionQueue.ts | 50 +++++++++++------------ src/state-manager/TransactionRepair.ts | 2 +- use_seqdiagram_logs.patch | 36 ++++++++++++++++ 8 files changed, 109 insertions(+), 77 deletions(-) create mode 100644 use_seqdiagram_logs.patch diff --git a/src/logger/index.ts b/src/logger/index.ts index cfff3d79a..f006b1510 100644 --- a/src/logger/index.ts +++ b/src/logger/index.ts @@ -339,14 +339,12 @@ class Logger { logFlags.fatal = true logFlags.important_as_fatal = true logFlags.playback = false - logFlags.seqdiagram = true } setDisableAllFlags() { for (const [key, value] of Object.entries(logFlags)) { logFlags[key] = false } - logFlags.seqdiagram = true } setErrorFlags() { @@ -359,7 +357,6 @@ class Logger { logFlags.important_as_error = true logFlags.playback = false - logFlags.seqdiagram = true //temp debug // logFlags.aalg = true @@ -382,8 +379,6 @@ class Logger { logFlags.important_as_fatal = true logFlags.important_as_error = true - logFlags.seqdiagram = true - //logFlags.rotation = true } diff --git a/src/p2p/Comms.ts b/src/p2p/Comms.ts index 8baa49993..70af38083 100644 --- a/src/p2p/Comms.ts +++ b/src/p2p/Comms.ts @@ -690,7 +690,7 @@ export function isNodeValidForInternalMessage( ): boolean { const logErrors = logFlags.debug if (node == null) { - seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: validnode ${NodeList.activeIdToPartition.get(node.id)} null`) + /* prettier-ignore */ if (logFlags.seqdiagram) seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: validnode ${NodeList.activeIdToPartition.get(node.id)} null`) if (logErrors) if (logFlags.error) /* prettier-ignore */ error(`isNodeValidForInternalMessage node == null ${utils.stringifyReduce(node.id)} ${debugMsg}`) @@ -700,7 +700,7 @@ export function isNodeValidForInternalMessage( // Some modes are not compatible with doing a valid node check for outgoing messages // if that is the case just return true and allow the message if (modeAllowsValidNodeChecks() === false) { - seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: validnode ${NodeList.activeIdToPartition.get(node.id)} nochecks`) + /* prettier-ignore */ if (logFlags.seqdiagram) seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: validnode ${NodeList.activeIdToPartition.get(node.id)} nochecks`) return true } @@ -718,10 +718,10 @@ export function isNodeValidForInternalMessage( // Also may add a flag to change if we also allow other statuses if (nodeStatus != 'active') { - seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: validnode ${NodeList.activeIdToPartition.get(node.id)} notactive`) + /* prettier-ignore */ if (logFlags.seqdiagram) seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: validnode ${NodeList.activeIdToPartition.get(node.id)} notactive`) } if (NodeList.potentiallyRemoved.has(node.id)) { - seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: validnode ${NodeList.activeIdToPartition.get(node.id)} remove`) + /* prettier-ignore */ if (logFlags.seqdiagram) seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: validnode ${NodeList.activeIdToPartition.get(node.id)} remove`) } // This is turned off and likely to be deleted. @@ -737,7 +737,7 @@ export function isNodeValidForInternalMessage( // //const isInRotationBounds = checkNodesRotationBounds && isNodeInRotationBounds(node.id) //if (isInRotationBounds) { - // seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: validnode ${NodeList.activeIdToPartition.get(node.id)} rotation`) + // /* prettier-ignore */ if (logFlags.seqdiagram) seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: validnode ${NodeList.activeIdToPartition.get(node.id)} rotation`) // return false //} @@ -782,7 +782,7 @@ export function isNodeValidForInternalMessage( if (logErrors) if (logFlags.error) /* prettier-ignore */ error(`isNodeValidForInternalMessage isNodeDown == true state:${state} ${utils.stringifyReduce(node.id)} ${debugMsg}`) - seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: validnode ${NodeList.activeIdToPartition.get(node.id)} down`) + /* prettier-ignore */ if (logFlags.seqdiagram) seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: validnode ${NodeList.activeIdToPartition.get(node.id)} down`) return false } } @@ -791,7 +791,7 @@ export function isNodeValidForInternalMessage( if (logErrors) if (logFlags.error) /* prettier-ignore */ error(`isNodeValidForInternalMessage isNodeLost == true ${utils.stringifyReduce(node.id)} ${debugMsg}`) - seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: validnode ${NodeList.activeIdToPartition.get(node.id)} lost`) + /* prettier-ignore */ if (logFlags.seqdiagram) seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: validnode ${NodeList.activeIdToPartition.get(node.id)} lost`) return false } } @@ -914,20 +914,20 @@ export async function sendGossip( //console.log('originIdx ', originIdx) if (context != '') - seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipContext:${context}`) + /* prettier-ignore */ if (logFlags.seqdiagram) seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipContext:${context}`) if (originIdx !== undefined && originIdx >= 0) { // If it is protocol tx signed by a node in the network recipientIdxs = utils.getLinearGossipBurstList(nodeIdxs.length, gossipFactor, myIdx, originIdx) if (logFlags.seqdiagram && txId != '') { - seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipBin:${nodeIdxs.length},${gossipFactor},${myIdx},${originIdx}`) - seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipBout:${recipientIdxs}`) + /* prettier-ignore */ if (logFlags.seqdiagram) seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipBin:${nodeIdxs.length},${gossipFactor},${myIdx},${originIdx}`) + /* prettier-ignore */ if (logFlags.seqdiagram) seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipBout:${recipientIdxs}`) } } else { // If it is app tx which is not signed by a node in the network recipientIdxs = utils.getLinearGossipList(nodeIdxs.length, gossipFactor, myIdx, isOrigin) if (logFlags.seqdiagram && txId != '') { - seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipLin:${nodeIdxs.length},${gossipFactor},${myIdx},${isOrigin}`) - seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipLout:${recipientIdxs}`) + /* prettier-ignore */ if (logFlags.seqdiagram) seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipLin:${nodeIdxs.length},${gossipFactor},${myIdx},${isOrigin}`) + /* prettier-ignore */ if (logFlags.seqdiagram) seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipLout:${recipientIdxs}`) } } @@ -983,7 +983,7 @@ export async function sendGossip( } else { /* prettier-ignore */ nestedCountersInstance.countEvent('p2p-skip-send', 'skipping gossip') /* prettier-ignore */ nestedCountersInstance.countEvent( 'p2p-skip-send', `skipping gossip ${node.internalIp}:${node.externalPort}` ) - seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipSkip:${NodeList.activeIdToPartition.get(node.id)}:${node.internalIp}:${node.externalPort}`) + /* prettier-ignore */ if (logFlags.seqdiagram) seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipSkip:${NodeList.activeIdToPartition.get(node.id)}:${node.internalIp}:${node.externalPort}`) } }) const newCount = recipients.length @@ -1005,7 +1005,7 @@ export async function sendGossip( if (context != '') suffix = `:${suffix}` for (const node of recipients) { - seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: g:${prefix}${type}${suffix}`) + /* prettier-ignore */ if (logFlags.seqdiagram) seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${txId} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: g:${prefix}${type}${suffix}`) } } diff --git a/src/rate-limiting/index.ts b/src/rate-limiting/index.ts index 8ff23534e..39684f9c4 100644 --- a/src/rate-limiting/index.ts +++ b/src/rate-limiting/index.ts @@ -6,6 +6,7 @@ import { shardusGetTime } from '../network' import { activeIdToPartition } from '../p2p/NodeList' import * as Self from '../p2p/Self' import * as Context from '../p2p/Context' +import { logFlags } from '../logger' interface RateLimiting { limitRate: boolean @@ -68,17 +69,17 @@ class RateLimiting { let overloaded = Math.random() < throttle if (overloaded) { - this.seqLogger.info( + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info( `0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get( Self.id )}: overloaded_type ${loadType}:${throttle}` ) - this.seqLogger.info( + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info( `0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get( Self.id )}: overloaded_node ${nodeLoad.internal}/${nodeLoad.external}` ) - this.seqLogger.info( + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info( `0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get( Self.id )}: overloaded_queue ${queueLoad.txTimeInQueue}/${queueLoad.queueLength}}/${ diff --git a/src/shardus/index.ts b/src/shardus/index.ts index 9fd15bac0..4723c42d7 100644 --- a/src/shardus/index.ts +++ b/src/shardus/index.ts @@ -1325,7 +1325,7 @@ class Shardus extends EventEmitter { ): Promise<{ success: boolean; reason: string; status: number, txId?: string }> { const noConsensus = set || global const txId = this.app.calculateTxId(tx); - this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: inject:${shardusGetTime()}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: inject:${shardusGetTime()}`) // Check if Consensor is ready to receive txs before processing it further if (!this.appProvided) @@ -1375,7 +1375,7 @@ class Shardus extends EventEmitter { } } if (this.rateLimiting.isOverloaded(txId)) { - this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: reject_overload`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: reject_overload`) this.statistics.incrementCounter('txRejected') nestedCountersInstance.countEvent('rejected', 'isOverloaded') return { success: false, reason: 'Maximum load exceeded.', status: 500 } @@ -1406,7 +1406,7 @@ class Shardus extends EventEmitter { } const senderAddress = this.app.getTxSenderAddress(tx); - this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: sender:${senderAddress}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: sender:${senderAddress}`) // Forward transaction to a node that has the account data locally if we don't have it if (global === false) { if (senderAddress == null) { @@ -1442,8 +1442,8 @@ class Shardus extends EventEmitter { if (internalTx === false) { let senderAccountNonce = await this.app.getAccountNonce(senderAddress); txNonce = await this.app.getNonceFromTx(tx); - this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: sNonce:${senderAccountNonce}`) - this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: txNonce:${txNonce}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: sNonce:${senderAccountNonce}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: txNonce:${txNonce}`) if (senderAccountNonce == null) { if (this.config.mode === ShardusTypes.ServerMode.Release) { @@ -1512,7 +1512,7 @@ class Shardus extends EventEmitter { //ITN fix. There will be separate effort to protect the pool more intelligently for mainnet. if(shouldQueueNonceButPoolIsFull) { - this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: reject_nonce_full`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: reject_nonce_full`) nestedCountersInstance.countEvent('rejected', `Nonce pool is full, try again later`) return { success: false, @@ -1588,7 +1588,7 @@ class Shardus extends EventEmitter { port: homeNode.node.externalPort, publicKey: homeNode.node.publicKey, }) - this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: lucky_forward_homenode_${context} ${activeIdToPartition.get(homeNode.node.id)}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: lucky_forward_homenode_${context} ${activeIdToPartition.get(homeNode.node.id)}`) let stats ={ skippedSelf:0, @@ -1597,7 +1597,7 @@ class Shardus extends EventEmitter { } for (const id of closetNodeIds) { - this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: lucky_forward_closetnode_${context} ${activeIdToPartition.get(id)}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: lucky_forward_closetnode_${context} ${activeIdToPartition.get(id)}`) if (id === Self.id) { stats.skippedSelf++ continue @@ -1631,7 +1631,7 @@ class Shardus extends EventEmitter { } for (const validator of selectedValidators) { try { - this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: lucky_forward_req_${context} ${activeIdToPartition.get(validator.id)}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: lucky_forward_req_${context} ${activeIdToPartition.get(validator.id)}`) if (validator.id === homeNode.node.id) { /* prettier-ignore */ if (logFlags.debug || logFlags.rotation) this.mainLogger.debug( `Forwarding injected tx ${txId} to home node ${validator.id} reason: ${message} ${utils.stringify(tx)}` ) @@ -1644,22 +1644,22 @@ class Shardus extends EventEmitter { const result: ShardusTypes.InjectTxResponse = await this.app.injectTxToConsensor([validator], tx) if (result == null) { - this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: lucky_forward_null_${context} ${activeIdToPartition.get(validator.id)}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: lucky_forward_null_${context} ${activeIdToPartition.get(validator.id)}`) /* prettier-ignore */ if (logFlags.debug || logFlags.rotation) this.mainLogger.debug( `Got null/undefined response upon forwarding injected tx: ${txId} to node ${validator.id}` ) continue } if (result && result.success === false) { - this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: lucky_forward_false_${context} ${activeIdToPartition.get(validator.id)}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: lucky_forward_false_${context} ${activeIdToPartition.get(validator.id)}`) /* prettier-ignore */ if (logFlags.debug || logFlags.rotation) this.mainLogger.debug( `Got unsuccessful response upon forwarding injected tx: ${validator.id}. ${message} ${utils.stringify(tx)}` ) continue } if (result && result.success === true) { - this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: lucky_forward_success_${context} ${activeIdToPartition.get(validator.id)}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: lucky_forward_success_${context} ${activeIdToPartition.get(validator.id)}`) /* prettier-ignore */ if (logFlags.debug || logFlags.rotation) this.mainLogger.debug( `Got successful response upon forwarding injected tx: ${validator.id}. ${message} ${utils.stringify(tx)}` ) return { success: true, reason: 'Transaction forwarded to validators', status: 200 } } } catch (e) { - this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: lucky_forward_ex_${context} ${activeIdToPartition.get(validator.id)}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${txId} Note over ${activeIdToPartition.get(Self.id)}: lucky_forward_ex_${context} ${activeIdToPartition.get(validator.id)}`) /* prettier-ignore */ if (logFlags.debug || logFlags.rotation) this.mainLogger.error( `Forwarding injected tx to ${validator.id} failed. ${message} ${utils.stringify(tx)} error: ${ e.stack }` ) } } diff --git a/src/state-manager/TransactionConsensus.ts b/src/state-manager/TransactionConsensus.ts index f16fb8aeb..bd65a5d73 100644 --- a/src/state-manager/TransactionConsensus.ts +++ b/src/state-manager/TransactionConsensus.ts @@ -557,14 +557,14 @@ class TransactionConsenus { try { const queueEntry = this.stateManager.transactionQueue.getQueueEntrySafe(payload.txid) // , payload.timestamp) if (queueEntry == null) { - this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${payload.txid} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:noTX`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${payload.txid} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:noTX`) return } const newVote = payload as AppliedVote const appendSuccessful = this.stateManager.transactionConsensus.tryAppendVote(queueEntry, newVote) if (appendSuccessful) { - this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${payload.txid} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:appended`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${payload.txid} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:appended`) const gossipGroup = this.stateManager.transactionQueue.queueEntryGetTransactionGroup(queueEntry) if (gossipGroup.length > 1) { // should consider only forwarding in some cases? @@ -1070,7 +1070,7 @@ class TransactionConsenus { let timestampReceipt try { if (this.config.p2p.useBinarySerializedEndpoints && this.config.p2p.getTxTimestampBinary) { - if (logFlags.seqdiagram) this.seqLogger.info(`0x53455101 ${shardusGetTime()} tx:${txId} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(homeNode.node.id)}: ${'get_tx_timestamp'}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455101 ${shardusGetTime()} tx:${txId} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(homeNode.node.id)}: ${'get_tx_timestamp'}`) const serialized_res = await this.p2p.askBinary( homeNode.node, InternalRouteEnum.binary_get_tx_timestamp, @@ -1922,7 +1922,7 @@ class TransactionConsenus { const queryData: AppliedVoteQuery = { txId: queueEntry.acceptedTx.txId } if (this.config.p2p.useBinarySerializedEndpoints && this.config.p2p.getAppliedVoteBinary) { const req = queryData as GetAppliedVoteReq - if (logFlags.seqdiagram) this.seqLogger.info(`0x53455101 ${shardusGetTime()} tx:${txId} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'get_applied_vote'}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455101 ${shardusGetTime()} tx:${txId} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'get_applied_vote'}`) const rBin = await Comms.askBinary( node, InternalRouteEnum.binary_get_applied_vote, @@ -1989,7 +1989,7 @@ class TransactionConsenus { const queryFn = async (node: Shardus.Node): Promise => { if (node.externalIp === Self.ip && node.externalPort === Self.port) return null const queryData = { txId: queueEntry.acceptedTx.txId } - if (logFlags.seqdiagram) this.seqLogger.info(`0x53455101 ${shardusGetTime()} tx:${queryData.txId} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'get_confirm_or_challenge'}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455101 ${shardusGetTime()} tx:${queryData.txId} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'get_confirm_or_challenge'}`) return this.config.p2p.useBinarySerializedEndpoints && this.config.p2p.getConfirmOrChallengeBinary ? await Comms.askBinary( node, @@ -2111,7 +2111,7 @@ class TransactionConsenus { try { if (this.config.p2p.useBinarySerializedEndpoints && this.config.p2p.getAccountDataBinary) { const req = message as GetAccountDataReqSerializable - if (logFlags.seqdiagram) this.seqLogger.info(`0x53455101 ${shardusGetTime()} tx:${txId} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'get_account_data3'}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455101 ${shardusGetTime()} tx:${txId} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'get_account_data3'}`) const rBin = await Comms.askBinary( node, InternalRouteEnum.binary_get_account_data, @@ -3068,9 +3068,9 @@ class TransactionConsenus { } else { if (queueEntry.acceptVoteMessage === false || queueEntry.appliedReceipt2 != null) { if (queueEntry.acceptVoteMessage === false) - this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:f no_accept`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:f no_accept`) if (queueEntry.appliedReceipt2 != null) - this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:f applied2_not_null`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:f applied2_not_null`) return false } /* prettier-ignore */ if (logFlags.playback) this.logger.playbackLogNote('tryAppendVote', `${queueEntry.logID}`, `vote: ${utils.stringifyReduce(vote)}`) @@ -3081,7 +3081,7 @@ class TransactionConsenus { this.crypto.verify(vote as SignedObject, queueEntry.executionGroupMap.get(vote.node_id).publicKey) if (!isEligibleToVote) { - this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:f not_eligible`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:f not_eligible`) if (logFlags.debug) { this.mainLogger.debug( `tryAppendVote: logId:${ @@ -3118,8 +3118,8 @@ class TransactionConsenus { receivedVoter = queueEntry.executionGroupMap.get(vote.node_id) as Shardus.NodeWithRank } isBetterThanCurrentVote = receivedVoter.rank > queueEntry.receivedBestVoter.rank - this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV ${receivedVoter.rank} > ${queueEntry.receivedBestVoter.rank}`) - this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV ${NodeList.activeIdToPartition.get(receivedVoter.id)} : ${NodeList.activeIdToPartition.get(queueEntry.receivedBestVoter.id)}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV ${receivedVoter.rank} > ${queueEntry.receivedBestVoter.rank}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV ${NodeList.activeIdToPartition.get(receivedVoter.id)} : ${NodeList.activeIdToPartition.get(queueEntry.receivedBestVoter.id)}`) } if (!isBetterThanCurrentVote) { @@ -3129,9 +3129,9 @@ class TransactionConsenus { ) } if (receivedVoter) - this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:f worser_voter ${NodeList.activeIdToPartition.get(receivedVoter.id)}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:f worser_voter ${NodeList.activeIdToPartition.get(receivedVoter.id)}`) else - this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:f worser_voter`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:f worser_voter`) return false } @@ -3145,17 +3145,17 @@ class TransactionConsenus { } if (receivedVoter) { queueEntry.receivedBestVoter = receivedVoter - this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:t receivedVoter ${NodeList.activeIdToPartition.get(receivedVoter.id)}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:t receivedVoter ${NodeList.activeIdToPartition.get(receivedVoter.id)}`) return true } else { if (queueEntry.executionGroupMap.has(vote.node_id)) { queueEntry.receivedBestVoter = queueEntry.executionGroupMap.get( vote.node_id ) as Shardus.NodeWithRank - this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:t receivedVoter2 ${NodeList.activeIdToPartition.get(queueEntry.receivedBestVoter.id)}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:t receivedVoter2 ${NodeList.activeIdToPartition.get(queueEntry.receivedBestVoter.id)}`) return true } - this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:f no_receivedVoter`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: gossipHandlerAV:f no_receivedVoter`) return false } // No need to forward the gossip here as it's being done in the gossip handler diff --git a/src/state-manager/TransactionQueue.ts b/src/state-manager/TransactionQueue.ts index efb33b7ab..8e99d6906 100644 --- a/src/state-manager/TransactionQueue.ts +++ b/src/state-manager/TransactionQueue.ts @@ -1003,7 +1003,7 @@ class TransactionQueue { queue = queue.sort((a, b) => Number(a.nonce) - Number(b.nonce)) this.nonceQueue.set(nonceQueueEntry.accountId, queue) } - this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${nonceQueueEntry.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: pause_nonceQ`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455106 ${shardusGetTime()} tx:${nonceQueueEntry.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: pause_nonceQ`) nestedCountersInstance.countEvent('processing', 'addTransactionToNonceQueue') if (logFlags.debug) this.mainLogger.debug(`Added tx to nonce queue for ${nonceQueueEntry.accountId} with nonce ${nonceQueueEntry.nonce} nonceQueue: ${queue.length}`) return { success: true, reason: `Nonce queue size for account: ${queue.length}` } @@ -2104,18 +2104,18 @@ class TransactionQueue { txQueueEntry.executionGroupMap.set(node.id, node) if (node.id === ourID) { txQueueEntry.ourExGroupIndex = idx - this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: executor index ${txQueueEntry.ourExGroupIndex}:${(node as Shardus.NodeWithRank).rank}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: executor index ${txQueueEntry.ourExGroupIndex}:${(node as Shardus.NodeWithRank).rank}`) } } if (txQueueEntry.eligibleNodeIdsToConfirm.has(Self.id)) { - this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: confirmator`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: confirmator`) } if (txQueueEntry.eligibleNodeIdsToVote.has(Self.id)) { - this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: voter`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: voter`) } - this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: groupsize voters ${txQueueEntry.eligibleNodeIdsToConfirm.size}`) - this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: groupsize confirmators ${txQueueEntry.eligibleNodeIdsToConfirm.size}`) - this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: groupsize execution ${txQueueEntry.executionGroup.length}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: groupsize voters ${txQueueEntry.eligibleNodeIdsToConfirm.size}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: groupsize confirmators ${txQueueEntry.eligibleNodeIdsToConfirm.size}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: groupsize execution ${txQueueEntry.executionGroup.length}`) //if we are not in the execution group then set isInExecutionHome to false @@ -2230,7 +2230,7 @@ class TransactionQueue { if (txQueueEntry.hasShardInfo) { const transactionGroup = this.queueEntryGetTransactionGroup(txQueueEntry) - this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: groupsize transaction ${txQueueEntry.transactionGroup.length}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: groupsize transaction ${txQueueEntry.transactionGroup.length}`) if (txQueueEntry.ourNodeInTransactionGroup || txQueueEntry.didSync === true) { // go ahead and calculate this now if we are in the tx group or we are syncing this range! this.queueEntryGetConsensusGroup(txQueueEntry) @@ -2303,7 +2303,7 @@ class TransactionQueue { ) { if (logFlags.seqdiagram) { for (const node of this.stateManager.currentCycleShardData.syncingNeighborsTxGroup) { - this.seqLogger.info(`0x53455102 ${shardusGetTime()} tx:${acceptedTx.txId} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'spread_tx_to_group_syncing'}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455102 ${shardusGetTime()} tx:${acceptedTx.txId} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'spread_tx_to_group_syncing'}`) } } const request = acceptedTx as SpreadTxToGroupSyncingReq @@ -2357,7 +2357,7 @@ class TransactionQueue { this.pendingTransactionQueue.push(txQueueEntry) this.pendingTransactionQueueByID.set(txQueueEntry.acceptedTx.txId, txQueueEntry) - if (logFlags.seqdiagram) this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${txQueueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: pendingQ`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${txQueueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: pendingQ`) /* prettier-ignore */ if (logFlags.playback) this.logger.playbackLogNote('shrd_txPreQueued', `${txQueueEntry.logID}`, `${txQueueEntry.logID} gm:${txQueueEntry.globalModification}`) // start the queue if needed @@ -2882,7 +2882,7 @@ class TransactionQueue { try { if (this.config.p2p.useBinarySerializedEndpoints && this.config.p2p.requestStateForTxBinary) { // GOLD-66 Error handling try/catch happens one layer outside of this function in process transactions - if (logFlags.seqdiagram) this.seqLogger.info(`0x53455101 ${shardusGetTime()} tx:${message.txid} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'request_state_for_tx'}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455101 ${shardusGetTime()} tx:${message.txid} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'request_state_for_tx'}`) result = (await this.p2p.askBinary( node, InternalRouteEnum.binary_request_state_for_tx, @@ -3071,7 +3071,7 @@ class TransactionQueue { this.stateManager.config.p2p.requestReceiptForTxBinary ) { try { - if (logFlags.seqdiagram) this.seqLogger.info(`0x53455101 ${shardusGetTime()} tx:${message.txid} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'request_receipt_for_tx'}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455101 ${shardusGetTime()} tx:${message.txid} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'request_receipt_for_tx'}`) result = await this.p2p.askBinary< RequestReceiptForTxReqSerialized, RequestReceiptForTxRespSerialized @@ -3428,7 +3428,7 @@ class TransactionQueue { /* prettier-ignore */ if (logFlags.verbose) this.mainLogger.debug(`queueEntryGetTransactionGroup not involved: hasNonG:${hasNonGlobalKeys} tx ${queueEntry.logID}`) } if (queueEntry.ourNodeInTransactionGroup) - this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: targetgroup`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: targetgroup`) // make sure our node is included: needed for gossip! - although we may not care about the data! // This may seem confusing, but to gossip to other nodes, we have to have our node in the list we will gossip to @@ -3904,9 +3904,9 @@ class TransactionQueue { if (logFlags.seqdiagram) { for (const node of nodes) { if (context == "tellCorrespondingNodes") { - this.seqLogger.info(`0x53455102 ${shardusGetTime()} tx:${message.txid} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'broadcast_state_nodes'}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455102 ${shardusGetTime()} tx:${message.txid} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'broadcast_state_nodes'}`) } else { - this.seqLogger.info(`0x53455102 ${shardusGetTime()} tx:${message.txid} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'broadcast_state_neighbour'}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455102 ${shardusGetTime()} tx:${message.txid} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'broadcast_state_neighbour'}`) } } } @@ -4430,7 +4430,7 @@ class TransactionQueue { const request = message as BroadcastFinalStateReq if (logFlags.seqdiagram) { for (const node of filterdCorrespondingAccNodes) { - this.seqLogger.info(`0x53455102 ${shardusGetTime()} tx:${message.txid} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'broadcast_finalstate'}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455102 ${shardusGetTime()} tx:${message.txid} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'broadcast_finalstate'}`) } } @@ -4554,7 +4554,7 @@ class TransactionQueue { */ removeFromQueue(queueEntry: QueueEntry, currentIndex: number, archive = true): void { // end all the pending txDebug timers - if (logFlags.seqdiagram) this.seqLogger.info(`0x53455104 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: removed`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455104 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: removed`) for (const key in queueEntry.txDebug.startTime) { if (queueEntry.txDebug.startTime[key] != null) { this.txDebugMarkEndTime(queueEntry, key) @@ -4794,7 +4794,7 @@ class TransactionQueue { this._transactionQueue.splice(index + 1, 0, txQueueEntry) this._transactionQueueByID.set(txQueueEntry.acceptedTx.txId, txQueueEntry) - if (logFlags.seqdiagram) this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${txQueueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: aging`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455105 ${shardusGetTime()} tx:${txQueueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: aging`) processStats.inserted++ @@ -5412,15 +5412,15 @@ class TransactionQueue { } else { const upstreamTx = this.processQueue_getUpstreamTx(seenAccounts, queueEntry) if (upstreamTx == null) { - if (logFlags.seqdiagram) this.seqLogger.info(`0x53455104 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: upstream:null`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455104 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: upstream:null`) nestedCountersInstance.countEvent('processing', 'busy waiting the upstream tx.' + ' but it is null') } else { if (upstreamTx.logID === queueEntry.logID) { - if (logFlags.seqdiagram) this.seqLogger.info(`0x53455104 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: upstream:same`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455104 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: upstream:same`) nestedCountersInstance.countEvent('processing', 'busy waiting the upstream tx but it is same txId') } else { - if (logFlags.seqdiagram) this.seqLogger.info(`0x53455104 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: upstream:${upstreamTx.logID}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455104 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: upstream:${upstreamTx.logID}`) nestedCountersInstance.countEvent('processing', `busy waiting the upstream tx to complete. state ${queueEntry.state}`) } } @@ -6701,7 +6701,7 @@ class TransactionQueue { let response if (this.config.p2p.useBinarySerializedEndpoints && this.config.p2p.requestTxAndStateBinary) { const requestMessage = message as RequestTxAndStateReq - if (logFlags.seqdiagram) this.seqLogger.info(`0x53455101 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(nodeToAsk.id)}: ${'request_tx_and_state'}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455101 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(nodeToAsk.id)}: ${'request_tx_and_state'}`) response = await Comms.askBinary( nodeToAsk, InternalRouteEnum.binary_request_tx_and_state, @@ -6794,7 +6794,7 @@ class TransactionQueue { } for (const key of queueEntry.uniqueKeys) { // eslint-disable-next-line security/detect-object-injection - if (logFlags.seqdiagram) this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: seenAccount:${key}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455103 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: seenAccount:${key}`) if (seenAccounts[key] != null) { return true } @@ -7551,9 +7551,9 @@ class TransactionQueue { updateTxState(queueEntry: QueueEntry, nextState: string, context = ''): void { if (logFlags.seqdiagram) if (context == '') - this.seqLogger.info(`0x53455104 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: ${queueEntry.state}-${nextState}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455104 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: ${queueEntry.state}-${nextState}`) else - this.seqLogger.info(`0x53455104 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: ${queueEntry.state}-${nextState}:${context}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455104 ${shardusGetTime()} tx:${queueEntry.acceptedTx.txId} Note over ${NodeList.activeIdToPartition.get(Self.id)}: ${queueEntry.state}-${nextState}:${context}`) const currentState = queueEntry.state this.txDebugMarkEndTime(queueEntry, currentState) queueEntry.state = nextState diff --git a/src/state-manager/TransactionRepair.ts b/src/state-manager/TransactionRepair.ts index 90d16b144..78ca0e9f3 100644 --- a/src/state-manager/TransactionRepair.ts +++ b/src/state-manager/TransactionRepair.ts @@ -573,7 +573,7 @@ class TransactionRepair { this.config.p2p.requestStateForTxPostBinary ) { const request = message as RequestStateForTxPostReq - if (logFlags.seqdiagram) this.seqLogger.info(`0x53455101 ${shardusGetTime()} tx:${message.txid} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'request_state_for_tx_post'}`) + /* prettier-ignore */ if (logFlags.seqdiagram) this.seqLogger.info(`0x53455101 ${shardusGetTime()} tx:${message.txid} ${NodeList.activeIdToPartition.get(Self.id)}-->>${NodeList.activeIdToPartition.get(node.id)}: ${'request_state_for_tx_post'}`) // GOLD-65 This only has a try /finally. repairToMatchReceipt is called in several places so it is better hanlde the error here result = await this.p2p.askBinary( node, diff --git a/use_seqdiagram_logs.patch b/use_seqdiagram_logs.patch new file mode 100644 index 000000000..17ebe8137 --- /dev/null +++ b/use_seqdiagram_logs.patch @@ -0,0 +1,36 @@ +diff --git a/src/logger/index.ts b/src/logger/index.ts +index f006b151..cfff3d79 100644 +--- a/src/logger/index.ts ++++ b/src/logger/index.ts +@@ -339,12 +339,14 @@ class Logger { + logFlags.fatal = true + logFlags.important_as_fatal = true + logFlags.playback = false ++ logFlags.seqdiagram = true + } + + setDisableAllFlags() { + for (const [key, value] of Object.entries(logFlags)) { + logFlags[key] = false + } ++ logFlags.seqdiagram = true + } + + setErrorFlags() { +@@ -357,6 +359,7 @@ class Logger { + logFlags.important_as_error = true + + logFlags.playback = false ++ logFlags.seqdiagram = true + + //temp debug + // logFlags.aalg = true +@@ -379,6 +382,8 @@ class Logger { + logFlags.important_as_fatal = true + logFlags.important_as_error = true + ++ logFlags.seqdiagram = true ++ + //logFlags.rotation = true + } +