From 58170cef3f844916af68dcb7d291cb8a40ca46b6 Mon Sep 17 00:00:00 2001 From: Marc Chiesa Date: Mon, 14 Aug 2023 10:20:36 -0400 Subject: [PATCH] Add extra logging and algorithm analysis --- README_CHIESA.md | 38 +++++++++++++++++++++ consensus/istanbul/qbft/core/commit.go | 3 ++ consensus/istanbul/qbft/core/core.go | 20 +++++++++++ consensus/istanbul/qbft/core/handler.go | 13 +++++++ consensus/istanbul/qbft/core/prepare.go | 5 +++ consensus/istanbul/qbft/core/preprepare.go | 8 +++++ consensus/istanbul/qbft/core/request.go | 8 +++++ consensus/istanbul/qbft/core/roundchange.go | 12 +++++++ internal/testlog/testlog.go | 8 +++++ log/format.go | 9 +++-- log/logger.go | 14 ++++++++ 11 files changed, 136 insertions(+), 2 deletions(-) create mode 100644 README_CHIESA.md diff --git a/README_CHIESA.md b/README_CHIESA.md new file mode 100644 index 0000000000..80635a23e7 --- /dev/null +++ b/README_CHIESA.md @@ -0,0 +1,38 @@ +## Build + +Just run `make all` and the binaries will be in `build\bin` + +Either add that directory to your path or copy the binaries to a location that is already on the path. + +## Running + +Set up two nodes on a private network based on the instructions at [this link](https://docs.goquorum.consensys.net/tutorials/private-network/create-qbft-network) + +Run the nodes with the following command lines: + +### Node 1 +`geth --datadir data --networkid 1337 --nodiscover --verbosity 5 --syncmode full --istanbul.blockperiod 5 --mine --miner.threads 1 --miner.gasprice 0 --emitcheckpoints --http --http.addr 127.0.0.1 --http.port 22000 --http.corsdomain "*" --http.vhosts "*" --ws --ws.addr 127.0.0.1 --ws.port 32000 --ws.origins "*" --http.api admin,eth,debug,miner,net,txpool,personal,web3,istanbul --ws.api admin,eth,debug,miner,net,txpool,personal,web3,istanbul --unlock ${ADDRESS} --allow-insecure-unlock --password ./data/keystore/accountPassword --port 30300 --miner.gaslimit 100000000000000000` + +### Node 2 +`geth --datadir data --networkid 1337 --nodiscover --verbosity 5 --syncmode full --istanbul.blockperiod 5 --mine --miner.threads 1 --miner.gasprice 0 --emitcheckpoints --http --http.addr 127.0.0.1 --http.port 22001 --http.corsdomain "*" --http.vhosts "*" --ws --ws.addr 127.0.0.1 --ws.port 32001 --ws.origins "*" --http.api admin,eth,debug,miner,net,txpool,personal,web3,istanbul --ws.api admin,eth,debug,miner,net,txpool,personal,web3,istanbul --unlock ${ADDRESS} --allow-insecure-unlock --password ./data/keystore/accountPassword --port 30301 --miner.gaslimit 1000000000000000` + +## Explanation of Behavior + +When there are a quorum of nodes available that are well-behaved, QBFT appears to behave as follows: + +* The validators wait for requests to arrive +* When a request is received, the block commit process starts with a pre-prepare message from the proposer +* The other validators receive the pre-prepare message and broadcast their own prepare messages +* Once a quorum of prepare messages has been received, they validators move to the commit phase +* When a quorum of commit messages has been received, the state transitions from prepared to committed +* Once in the committed state, the new block is added +* The validators go back to waiting for requests + +When things are in a bad state, such as when there are no longer enough nodes for a quorum: + +* The round change timer expires. +* The round increases and the timeout grows. +* While the number of nodes is under the minimum needed for consensus, no blocks can be validated/committed +* With our simple two-node network, both nodes are needed for a quorum. +* When the number of nodes reaches the threshold required for a quorum, block processing can continue. +* The round number will reset and the round timeouts will fall back to the lowest setting (10 seconds) diff --git a/consensus/istanbul/qbft/core/commit.go b/consensus/istanbul/qbft/core/commit.go index 3dce6c36e0..00932ef49a 100644 --- a/consensus/istanbul/qbft/core/commit.go +++ b/consensus/istanbul/qbft/core/commit.go @@ -20,6 +20,7 @@ import ( "github.com/ethereum/go-ethereum/common/hexutil" qbfttypes "github.com/ethereum/go-ethereum/consensus/istanbul/qbft/types" "github.com/ethereum/go-ethereum/core/types" + "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/rlp" ) @@ -87,6 +88,7 @@ func (c *core) broadcastCommit() { // - when quorum of COMMIT messages is reached then update state and commits func (c *core) handleCommitMsg(commit *qbfttypes.Commit) error { logger := c.currentLogger(true, commit) + logger.Marc(log.LvlTrace, "VALIDATING COMMIT MESSAGE") logger.Info("QBFT: handle COMMIT message", "commits.count", c.current.QBFTCommits.Size(), "quorum", c.QuorumSize()) @@ -107,6 +109,7 @@ func (c *core) handleCommitMsg(commit *qbfttypes.Commit) error { // If we reached thresho if c.current.QBFTCommits.Size() >= c.QuorumSize() { logger.Info("QBFT: received quorum of COMMIT messages") + logger.Marc(log.LvlTrace, "RECEIVED QUORUM OF COMMIT MESSAGES, MOVING TO COMMIT QBFT") c.commitQBFT() } else { logger.Debug("QBFT: accepted new COMMIT messages") diff --git a/consensus/istanbul/qbft/core/core.go b/consensus/istanbul/qbft/core/core.go index 20bd1569c3..0c04768932 100644 --- a/consensus/istanbul/qbft/core/core.go +++ b/consensus/istanbul/qbft/core/core.go @@ -17,6 +17,7 @@ package core import ( + "fmt" "math" "math/big" "sync" @@ -107,6 +108,9 @@ func (c *core) IsProposer() bool { if v == nil { return false } + if v.IsProposer(c.backend.Address()) { + c.logger.Marc(log.LvlTrace, "I AM THE PROPOSER NODE") + } return v.IsProposer(c.backend.Address()) } @@ -136,6 +140,7 @@ func (c *core) startNewRound(round *big.Int) { if c.current == nil { logger.Debug("QBFT: start at the initial round") + logger.Marc(log.LvlTrace, "STARTING AT THE INITIAL ROUND BECAUSE CURRENT STATE IS NIL") } else if lastProposal.Number().Cmp(c.current.Sequence()) >= 0 { diff := new(big.Int).Sub(lastProposal.Number(), c.current.Sequence()) sequenceMeter.Mark(new(big.Int).Add(diff, common.Big1).Int64()) @@ -144,16 +149,20 @@ func (c *core) startNewRound(round *big.Int) { consensusTimer.UpdateSince(c.consensusTimestamp) c.consensusTimestamp = time.Time{} } + logger.Marc(log.LvlTrace, "CATCHING UP TO LAST PROPOSAL") logger.Debug("QBFT: catch up last block proposal") } else if lastProposal.Number().Cmp(big.NewInt(c.current.Sequence().Int64()-1)) == 0 { if round.Cmp(common.Big0) == 0 { // same seq and round, don't need to start new round + logger.Marc(log.LvlTrace, "THE PROPOSED ROUND IS EQUAL TO THE CURRENT ROUND, NO CHANGE NECESSARY") logger.Debug("QBFT: same round, no need to start new round") return } else if round.Cmp(c.current.Round()) < 0 { + logger.Marc(log.LvlWarn, "THE PROPOSED ROUND IS LESS THAN THE CURRENT ROUND, NO CHANGE NECESSARY") logger.Warn("QBFT: next round is inferior to current round") return } + logger.Marc(log.LvlInfo, "A ROUND CHANGE IS NEEDED") roundChange = true } else { logger.Warn("QBFT: next sequence is before last block proposal") @@ -162,8 +171,10 @@ func (c *core) startNewRound(round *big.Int) { var oldLogger log.Logger if c.current == nil { + logger.Marc(log.LvlInfo, "JUST STARTED, NO PREVIOUS ROUND DATA TO RECORD") oldLogger = c.logger.New("old.round", -1, "old.seq", 0) } else { + logger.Marc(log.LvlInfo, fmt.Sprintf("ROUND: %d, SEQUENCE: %d", c.current.Round().Uint64(), c.current.Sequence().Uint64())) oldLogger = c.logger.New("old.round", c.current.Round().Uint64(), "old.sequence", c.current.Sequence().Uint64(), "old.state", c.state.String(), "old.proposer", c.valSet.GetProposer()) } @@ -187,6 +198,7 @@ func (c *core) startNewRound(round *big.Int) { // Calculate new proposer c.valSet.CalcProposer(lastProposer, newView.Round.Uint64()) + c.logger.Marc(log.LvlTrace, fmt.Sprintf("PROPOSER CALCULATION RESULT: %s", c.valSet.GetProposer().String())) c.setState(StateAcceptRequest) if c.current != nil && round.Cmp(c.current.Round()) > 0 { @@ -201,9 +213,11 @@ func (c *core) startNewRound(round *big.Int) { // Clear earlier round messages c.roundChangeSet.ClearLowerThan(round) } + logger.Marc(log.LvlTrace, "STARTING NEW ROUND") c.roundChangeSet.NewRound(round) if round.Uint64() > 0 { + logger.Marc(log.LvlTrace, "STARTING ROUND CHANGE TIMER") c.newRoundChangeTimer() } @@ -223,14 +237,17 @@ func (c *core) setState(state State) { if c.state != state { oldState := c.state c.state = state + c.logger.Marc(log.LvlTrace, fmt.Sprintf("STATE CHANGE: OLD STATE: %s; NEW STATE: %s", oldState.String(), state.String())) c.currentLogger(false, nil).Info("QBFT: changed state", "old.state", oldState.String(), "new.state", state.String()) } if state == StateAcceptRequest { + c.logger.Marc(log.LvlInfo, "STATE: PROCESSING PENDING REQUESTS") c.processPendingRequests() } // each time we change state, we process backlog for possible message that are // now ready + c.logger.Marc(log.LvlInfo, "PROCESSING BACKLOG") c.processBacklog() } @@ -270,6 +287,7 @@ func (c *core) newRoundChangeTimer() { timeout = maxRequestTimeout } + c.logger.Marc(log.LvlTrace, fmt.Sprintf("NEW ROUND CHANGE TIME WITH TIMEOUT %g SECONDS", timeout.Seconds())) c.currentLogger(true, nil).Trace("QBFT: start new ROUND-CHANGE timer", "timeout", timeout.Seconds()) c.roundChangeTimer = time.AfterFunc(timeout, func() { c.sendEvent(timeoutEvent{}) @@ -283,9 +301,11 @@ func (c *core) checkValidatorSignature(data []byte, sig []byte) (common.Address, func (c *core) QuorumSize() int { if c.config.Get2FPlus1Enabled(c.current.sequence) || c.config.Ceil2Nby3Block == nil || (c.current != nil && c.current.sequence.Cmp(c.config.Ceil2Nby3Block) < 0) { c.currentLogger(true, nil).Trace("QBFT: confirmation Formula used 2F+ 1") + c.logger.Marc(log.LvlInfo, fmt.Sprintf("2F+1 Quorum size: %d", (2*c.valSet.F())+1)) return (2 * c.valSet.F()) + 1 } c.currentLogger(true, nil).Trace("QBFT: confirmation Formula used ceil(2N/3)") + c.logger.Marc(log.LvlInfo, fmt.Sprintf("ceil(2N/3) Quorum size: %d", int(math.Ceil(float64(2*c.valSet.Size())/3)))) return int(math.Ceil(float64(2*c.valSet.Size()) / 3)) } diff --git a/consensus/istanbul/qbft/core/handler.go b/consensus/istanbul/qbft/core/handler.go index e77f7087ae..9aeaff7efd 100644 --- a/consensus/istanbul/qbft/core/handler.go +++ b/consensus/istanbul/qbft/core/handler.go @@ -99,6 +99,7 @@ func (c *core) handleEvents() { }() for { + c.logger.Marc(log.LvlTrace, "MAIN EVENT HANDLING LOOP") select { case event, ok := <-c.events.Chan(): if !ok { @@ -112,6 +113,7 @@ func (c *core) handleEvents() { r := &Request{ Proposal: ev.Proposal, } + c.logger.Marc(log.LvlTrace, "HANDLE REQUEST") err := c.handleRequest(r) if err == errFutureMessage { // store request for later treatment @@ -119,6 +121,7 @@ func (c *core) handleEvents() { } case istanbul.MessageEvent: // we received a message from another validator + c.logger.Marc(log.LvlTrace, "HANDLE MESSAGE FROM VALIDATOR") if err := c.handleEncodedMsg(ev.Code, ev.Payload); err != nil { continue } @@ -128,6 +131,7 @@ func (c *core) handleEvents() { case backlogEvent: // we process again a future message that was backlogged // no need to check signature as it was already node when we first received message + c.logger.Marc(log.LvlTrace, "HANDLE DECODED MESSAGE ON BACKLOG") if err := c.handleDecodedMessage(ev.msg); err != nil { continue } @@ -152,6 +156,7 @@ func (c *core) handleEvents() { if !ok { return } + c.logger.Marc(log.LvlTrace, "HANDLE COMMITTED") switch event.Data.(type) { case istanbul.FinalCommittedEvent: c.handleFinalCommitted() @@ -180,6 +185,8 @@ func (c *core) handleEncodedMsg(code uint64, data []byte) error { return err } + c.logger.Marc(log.LvlTrace, "MESSAGE DECODED, HANDLING") + // Verify signatures and set source address if err = c.verifySignatures(m); err != nil { return err @@ -193,6 +200,7 @@ func (c *core) handleDecodedMessage(m qbfttypes.QBFTMessage) error { if err := c.checkMessage(m.Code(), &view); err != nil { // Store in the backlog it it's a future message if err == errFutureMessage { + c.logger.Marc(log.LvlTrace, "FUTURE MESSAGE, ADDING TO BACKLOG") c.addToBacklog(m) } return err @@ -207,12 +215,16 @@ func (c *core) deliverMessage(m qbfttypes.QBFTMessage) error { switch m.Code() { case qbfttypes.PreprepareCode: + c.logger.Marc(log.LvlTrace, "MESSAGE WAS PREPREPARE") err = c.handlePreprepareMsg(m.(*qbfttypes.Preprepare)) case qbfttypes.PrepareCode: + c.logger.Marc(log.LvlTrace, "MESSAGE WAS PREPARE") err = c.handlePrepare(m.(*qbfttypes.Prepare)) case qbfttypes.CommitCode: + c.logger.Marc(log.LvlTrace, "MESSAGE WAS COMMIT") err = c.handleCommitMsg(m.(*qbfttypes.Commit)) case qbfttypes.RoundChangeCode: + c.logger.Marc(log.LvlTrace, "MESSAGE WAS ROUND CHANGE") err = c.handleRoundChange(m.(*qbfttypes.RoundChange)) default: c.logger.Error("QBFT: invalid message code", "code", m.Code()) @@ -224,6 +236,7 @@ func (c *core) deliverMessage(m qbfttypes.QBFTMessage) error { func (c *core) handleTimeoutMsg() { logger := c.currentLogger(true, nil) + logger.Marc(log.LvlTrace, "HANDLING ROUND CHANGE TIMEOUT MESSAGE") // Start the new round round := c.current.Round() nextRound := new(big.Int).Add(round, common.Big1) diff --git a/consensus/istanbul/qbft/core/prepare.go b/consensus/istanbul/qbft/core/prepare.go index 1ee6edfe15..462bfad640 100644 --- a/consensus/istanbul/qbft/core/prepare.go +++ b/consensus/istanbul/qbft/core/prepare.go @@ -19,6 +19,7 @@ package core import ( "github.com/ethereum/go-ethereum/common/hexutil" qbfttypes "github.com/ethereum/go-ethereum/consensus/istanbul/qbft/types" + "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/rlp" ) @@ -72,6 +73,7 @@ func (c *core) broadcastPrepare() { // - when quorum is reached update states to "Prepared" and broadcast COMMIT func (c *core) handlePrepare(prepare *qbfttypes.Prepare) error { logger := c.currentLogger(true, prepare).New() + logger.Marc(log.LvlTrace, "VALIDATING PREPARE MESSAGE") logger.Info("QBFT: handle PREPARE message", "prepares.count", c.current.QBFTPrepares.Size(), "quorum", c.QuorumSize()) @@ -94,6 +96,8 @@ func (c *core) handlePrepare(prepare *qbfttypes.Prepare) error { if (c.current.QBFTPrepares.Size() >= c.QuorumSize()) && c.state.Cmp(StatePrepared) < 0 { logger.Info("QBFT: received quorum of PREPARE messages") + logger.Marc(log.LvlTrace, "QUORUM OF PREPARE MESSAGES RECEIVED") + // Accumulates PREPARE messages c.current.preparedRound = c.currentView().Round c.QBFTPreparedPrepares = make([]*qbfttypes.Prepare, 0) @@ -109,6 +113,7 @@ func (c *core) handlePrepare(prepare *qbfttypes.Prepare) error { c.current.preparedBlock = c.current.Proposal() } + logger.Marc(log.LvlTrace, "SETTING STATE TO PREPARED AND MOVING TO BROADCAST COMMIT") c.setState(StatePrepared) c.broadcastCommit() } else { diff --git a/consensus/istanbul/qbft/core/preprepare.go b/consensus/istanbul/qbft/core/preprepare.go index 31305ec5aa..44af8ba2d3 100644 --- a/consensus/istanbul/qbft/core/preprepare.go +++ b/consensus/istanbul/qbft/core/preprepare.go @@ -22,6 +22,7 @@ import ( "github.com/ethereum/go-ethereum/common/hexutil" "github.com/ethereum/go-ethereum/consensus" qbfttypes "github.com/ethereum/go-ethereum/consensus/istanbul/qbft/types" + "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/rlp" ) @@ -38,6 +39,7 @@ func (c *core) sendPreprepareMsg(request *Request) { // If I'm the proposer and I have the same sequence with the proposal if c.current.Sequence().Cmp(request.Proposal.Number()) == 0 && c.IsProposer() { + c.logger.Marc(log.LvlTrace, "CREATING AND SIGNING PREPREPARE MESASGE WITH BLOCK PROPOSED AS PROPOSER") // Creates PRE-PREPARE message curView := c.currentView() preprepare := qbfttypes.NewPreprepare(curView.Sequence, curView.Round, request.Proposal) @@ -102,6 +104,7 @@ func (c *core) sendPreprepareMsg(request *Request) { // - validates PRE-PREPARE message block proposal func (c *core) handlePreprepareMsg(preprepare *qbfttypes.Preprepare) error { logger := c.currentLogger(true, preprepare) + logger.Marc(log.LvlTrace, "HANDLING PRE-PREPARE MESSAGE") logger = logger.New("proposal.number", preprepare.Proposal.Number().Uint64(), "proposal.hash", preprepare.Proposal.Hash().String()) @@ -123,8 +126,10 @@ func (c *core) handlePreprepareMsg(preprepare *qbfttypes.Preprepare) error { // Validates PRE-PREPARE block proposal we received if duration, err := c.backend.Verify(preprepare.Proposal); err != nil { + logger.Marc(log.LvlTrace, "PRE-PREPARE VERIFICATION ERROR") // if it's a future block, we will handle it again after the duration if err == consensus.ErrFutureBlock { + logger.Marc(log.LvlTrace, "PROPOSAL IS FOR FUTURE BLOCK, TO BE HANDLED LATER") logger.Info("QBFT: PRE-PREPARE block proposal is in the future (will be treated again later)", "duration", duration) // start a timer to re-input PRE-PREPARE message as a backlog event @@ -146,8 +151,10 @@ func (c *core) handlePreprepareMsg(preprepare *qbfttypes.Preprepare) error { // Here is about to accept the PRE-PREPARE if c.state == StateAcceptRequest { c.logger.Info("QBFT: accepted PRE-PREPARE message") + logger.Marc(log.LvlTrace, "ACCEPTED PRE-PREPARE MESSAGE") // Re-initialize ROUND-CHANGE timer + logger.Marc(log.LvlTrace, "STARTING NEW ROUND CHANGE TIMER") c.newRoundChangeTimer() c.consensusTimestamp = time.Now() @@ -156,6 +163,7 @@ func (c *core) handlePreprepareMsg(preprepare *qbfttypes.Preprepare) error { c.setState(StatePreprepared) // Broadcast prepare message to other validators + logger.Marc(log.LvlTrace, "BROADCASTING PREPARE MESSAGE TO VALIDATORS") c.broadcastPrepare() } diff --git a/consensus/istanbul/qbft/core/request.go b/consensus/istanbul/qbft/core/request.go index 0d9d5df1c0..89ee7bfb20 100644 --- a/consensus/istanbul/qbft/core/request.go +++ b/consensus/istanbul/qbft/core/request.go @@ -17,6 +17,7 @@ package core import ( + "fmt" "time" "github.com/ethereum/go-ethereum/consensus/istanbul" @@ -46,12 +47,15 @@ func (c *core) handleRequest(request *Request) error { c.current.pendingRequest = request if c.state == StateAcceptRequest { + logger.Marc(log.LvlTrace, "STATE: ACCEPT REQUEST") config := c.config.GetConfig(c.current.Sequence()) if config.EmptyBlockPeriod == 0 { // emptyBlockPeriod is not set // Start ROUND-CHANGE timer + c.logger.Marc(log.LvlTrace, "START ROUND CHANGE TIMER") c.newRoundChangeTimer() // Send PRE-PREPARE message to other validators + c.logger.Marc(log.LvlTrace, "SENDING PREPREPARE") c.sendPreprepareMsg(request) } else { // emptyBlockPeriod is set c.newRoundMutex.Lock() @@ -79,15 +83,19 @@ func (c *core) handleRequest(request *Request) error { } } if delay > 0 { + logger.Marc(log.LvlTrace, fmt.Sprintf("DELAYING START OF ROUND CHANGE TIMER BY %d millis", delay.Milliseconds())) c.newRoundTimer = time.AfterFunc(delay, func() { c.newRoundTimer = nil // Start ROUND-CHANGE timer c.newRoundChangeTimer() + logger.Marc(log.LvlTrace, "ROUND CHANGE TIMER STARTED, SENDING PREPREPARE MSG") // Send PRE-PREPARE message to other validators c.sendPreprepareMsg(request) }) } else { + logger.Marc(log.LvlTrace, "STARTING ROUND CHANGE TIMER IMMEDIATELY AND SENDING PREPREPARE MSG") + // Start ROUND-CHANGE timer c.newRoundChangeTimer() diff --git a/consensus/istanbul/qbft/core/roundchange.go b/consensus/istanbul/qbft/core/roundchange.go index a2a77f8ecd..66cdf52c02 100644 --- a/consensus/istanbul/qbft/core/roundchange.go +++ b/consensus/istanbul/qbft/core/roundchange.go @@ -18,6 +18,7 @@ package core import ( "errors" + "fmt" "math/big" "sort" "sync" @@ -47,6 +48,7 @@ func (c *core) broadcastNextRoundChange() { func (c *core) broadcastRoundChange(round *big.Int) { logger := c.currentLogger(true, nil) + logger.Marc(log.LvlTrace, "BROADCAST ROUND CHANGE") // Validates new round corresponds to current view cv := c.currentView() if cv.Round.Cmp(round) > 0 { @@ -96,6 +98,7 @@ func (c *core) broadcastRoundChange(round *big.Int) { // - when quorum of ROUND-CHANGE messages is reached then func (c *core) handleRoundChange(roundChange *qbfttypes.RoundChange) error { logger := c.currentLogger(true, roundChange) + logger.Marc(log.LvlTrace, "RECEIVED ROUND CHANGE MESSAGE FROM VALIDATOR") view := roundChange.View() currentRound := c.currentView().Round @@ -106,6 +109,7 @@ func (c *core) handleRoundChange(roundChange *qbfttypes.RoundChange) error { // number of validators we received ROUND-CHANGE from for the current round currentRoundMessages := c.roundChangeSet.getRCMessagesForGivenRound(currentRound) + logger.Marc(log.LvlTrace, fmt.Sprintf("RECEIVED A TOTAL OF %d ROUND CHANGES WITH HIGHER ROUND CHANGE FROM %d VALIDATORS.", num, currentRoundMessages)) logger.Info("QBFT: handle ROUND-CHANGE message", "higherRoundChanges.count", num, "currentRoundChanges.count", currentRoundMessages) // Add ROUND-CHANGE message to message set @@ -131,6 +135,8 @@ func (c *core) handleRoundChange(roundChange *qbfttypes.RoundChange) error { // number of validators we received ROUND-CHANGE from for the current round currentRoundMessages = c.roundChangeSet.getRCMessagesForGivenRound(currentRound) + logger.Marc(log.LvlTrace, fmt.Sprintf("RECEIVED A TOTAL OF %d ROUND CHANGES WITH HIGHER ROUND CHANGE FROM %d VALIDATORS.", num, currentRoundMessages)) + logger = logger.New("higherRoundChanges.count", num, "currentRoundChanges.count", currentRoundMessages) if num == c.valSet.F()+1 { @@ -138,6 +144,8 @@ func (c *core) handleRoundChange(roundChange *qbfttypes.RoundChange) error { // we start new round and broadcast ROUND-CHANGE message newRound := c.roundChangeSet.getMinRoundChange(currentRound) + logger.Marc(log.LvlTrace, "RECEIVED F+1 ROUND CHANGE MESSAGES, STARTING NEW ROUND") + logger.Info("QBFT: received F+1 ROUND-CHANGE messages", "F", c.valSet.F()) c.startNewRound(newRound) @@ -145,6 +153,8 @@ func (c *core) handleRoundChange(roundChange *qbfttypes.RoundChange) error { } else if currentRoundMessages >= c.QuorumSize() && c.IsProposer() && c.current.preprepareSent.Cmp(currentRound) < 0 { logger.Info("QBFT: received quorum of ROUND-CHANGE messages") + logger.Marc(log.LvlTrace, "RECEIVED QUORUM OF ROUND CHANGE MESSAGES AS PROPOSER") + // We received quorum of ROUND-CHANGE for current round and we are proposer // If we have received a quorum of PREPARE message @@ -160,6 +170,7 @@ func (c *core) handleRoundChange(roundChange *qbfttypes.RoundChange) error { } } + logger.Marc(log.LvlTrace, "PREPARE JUSTIFICATION FOR ROUND CHANGE MESSAGES") // Prepare justification for ROUND-CHANGE messages roundChangeMessages := c.roundChangeSet.roundChanges[currentRound.Uint64()] rcSignedPayloads := make([]*qbfttypes.SignedRoundChangePayload, 0) @@ -179,6 +190,7 @@ func (c *core) handleRoundChange(roundChange *qbfttypes.RoundChange) error { RCMessages: roundChangeMessages, PrepareMessages: prepareMessages, } + logger.Marc(log.LvlTrace, "SEND PREPREPARE MESSAGE") c.sendPreprepareMsg(r) } else { logger.Debug("QBFT: accepted ROUND-CHANGE messages") diff --git a/internal/testlog/testlog.go b/internal/testlog/testlog.go index 684339f16d..4af2f3b107 100644 --- a/internal/testlog/testlog.go +++ b/internal/testlog/testlog.go @@ -80,6 +80,14 @@ func (l *logger) Trace(msg string, ctx ...interface{}) { l.flush() } +func (l *logger) Marc(lvl log.Lvl, msg string, ctx ...interface{}) { + l.t.Helper() + l.mu.Lock() + defer l.mu.Unlock() + l.l.Marc(lvl, msg, ctx...) + l.flush() +} + func (l *logger) Debug(msg string, ctx ...interface{}) { l.t.Helper() l.mu.Lock() diff --git a/log/format.go b/log/format.go index 613dc33be7..157cded7af 100644 --- a/log/format.go +++ b/log/format.go @@ -104,6 +104,11 @@ func TerminalFormat(usecolor bool) Format { } } + msgColor := 0 + if r.Marc { + msgColor = 91 + } + b := &bytes.Buffer{} lvl := r.Lvl.AlignedString() if atomic.LoadUint32(&locationEnabled) != 0 { @@ -122,13 +127,13 @@ func TerminalFormat(usecolor bool) Format { // Assemble and print the log heading if color > 0 { - fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s|%s]%s %s ", color, lvl, r.Time.Format(termTimeFormat), location, padding, r.Msg) + fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s|%s]%s \x1b[%dm%s\x1b[0m ", color, lvl, r.Time.Format(termTimeFormat), location, padding, msgColor, r.Msg) } else { fmt.Fprintf(b, "%s[%s|%s]%s %s ", lvl, r.Time.Format(termTimeFormat), location, padding, r.Msg) } } else { if color > 0 { - fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s] %s ", color, lvl, r.Time.Format(termTimeFormat), r.Msg) + fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s] \x1b[%dm%s\x1b[0m ", color, lvl, r.Time.Format(termTimeFormat), msgColor, r.Msg) } else { fmt.Fprintf(b, "%s[%s] %s ", lvl, r.Time.Format(termTimeFormat), r.Msg) } diff --git a/log/logger.go b/log/logger.go index 276d6969e2..f741bc7129 100644 --- a/log/logger.go +++ b/log/logger.go @@ -24,6 +24,7 @@ const ( LvlInfo LvlDebug LvlTrace + LvlMarc = 1 << 31 ) // AlignedString returns a 5-character string containing the name of a Lvl. @@ -95,6 +96,7 @@ type Record struct { Ctx []interface{} Call stack.Call KeyNames RecordKeyNames + Marc bool } // RecordKeyNames gets stored in a Record when the write function is executed. @@ -123,6 +125,7 @@ type Logger interface { Warn(msg string, ctx ...interface{}) Error(msg string, ctx ...interface{}) Crit(msg string, ctx ...interface{}) + Marc(lvl Lvl, msg string, ctx ...interface{}) } type logger struct { @@ -131,6 +134,12 @@ type logger struct { } func (l *logger) write(msg string, lvl Lvl, ctx []interface{}, skip int) { + marc := false + if lvl&LvlMarc != 0 { + lvl ^= LvlMarc + marc = true + } + l.h.Log(&Record{ Time: time.Now(), Lvl: lvl, @@ -143,6 +152,7 @@ func (l *logger) write(msg string, lvl Lvl, ctx []interface{}, skip int) { Lvl: lvlKey, Ctx: ctxKey, }, + Marc: marc, }) } @@ -164,6 +174,10 @@ func (l *logger) Trace(msg string, ctx ...interface{}) { l.write(msg, LvlTrace, ctx, skipLevel) } +func (l *logger) Marc(lvl Lvl, msg string, ctx ...interface{}) { + l.write(msg, lvl|LvlMarc, ctx, skipLevel) +} + func (l *logger) Debug(msg string, ctx ...interface{}) { l.write(msg, LvlDebug, ctx, skipLevel) }