Skip to content

Commit

Permalink
feat: use logFlags.seqdiagram for all uses of seqLogger
Browse files Browse the repository at this point in the history 
feat(logger): never set `seqdiagram` to true by default

feat: add use_seqdiagram_logs.patch
  • Loading branch information
@muni-corn @mhanson-github
muni-corn authored and mhanson-github committed Jun 6, 2024
1 parent 2d10da4 commit 2fdf5ec
Show file tree
Hide file tree
Showing 8 changed files with 109 additions and 77 deletions.
5 changes: 0 additions & 5 deletions src/logger/index.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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() {
Expand All @@ -359,7 +357,6 @@ class Logger {
logFlags.important_as_error = true

logFlags.playback = false
logFlags.seqdiagram = true

//temp debug
// logFlags.aalg = true
Expand All @@ -382,8 +379,6 @@ class Logger {
logFlags.important_as_fatal = true
logFlags.important_as_error = true

logFlags.seqdiagram = true

//logFlags.rotation = true
}

Expand Down
28 changes: 14 additions & 14 deletions src/p2p/Comms.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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}`)
Expand All @@ -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
}

Expand All @@ -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.
Expand All @@ -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
//}

Expand Down Expand Up @@ -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
}
}
Expand All @@ -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
}
}
Expand Down Expand Up @@ -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}`)
}
}

Expand Down Expand Up @@ -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
Expand All @@ -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}`)
}
}

Expand Down
7 changes: 4 additions & 3 deletions src/rate-limiting/index.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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}}/${
Expand Down
26 changes: 13 additions & 13 deletions src/shardus/index.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -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 }
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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,
Expand All @@ -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
Expand Down Expand Up @@ -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)}` )
Expand All @@ -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 }` )
}
}
Expand Down
Loading

0 comments on commit 2fdf5ec

Please sign in to comment.