diff options
-rw-r--r-- | common/logger.go | 87 | ||||
-rw-r--r-- | core/configuration-chain.go | 36 | ||||
-rw-r--r-- | core/configuration-chain_test.go | 3 | ||||
-rw-r--r-- | core/consensus.go | 143 | ||||
-rw-r--r-- | core/consensus_test.go | 4 | ||||
-rw-r--r-- | core/lattice.go | 12 | ||||
-rw-r--r-- | core/lattice_test.go | 3 | ||||
-rw-r--r-- | core/types/block-randomness.go | 7 | ||||
-rw-r--r-- | core/types/dkg.go | 17 | ||||
-rw-r--r-- | core/types/position.go | 9 | ||||
-rw-r--r-- | integration_test/node.go | 3 | ||||
-rw-r--r-- | simulation/node.go | 8 |
12 files changed, 280 insertions, 52 deletions
diff --git a/common/logger.go b/common/logger.go new file mode 100644 index 0000000..9dc5d23 --- /dev/null +++ b/common/logger.go @@ -0,0 +1,87 @@ +// Copyright 2018 The dexon-consensus-core Authors +// This file is part of the dexon-consensus-core library. +// +// The dexon-consensus-core library is free software: you can redistribute it +// and/or modify it under the terms of the GNU Lesser General Public License as +// published by the Free Software Foundation, either version 3 of the License, +// or (at your option) any later version. +// +// The dexon-consensus-core library is distributed in the hope that it will be +// useful, but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU Lesser +// General Public License for more details. +// +// You should have received a copy of the GNU Lesser General Public License +// along with the dexon-consensus-core library. If not, see +// <http://www.gnu.org/licenses/>. + +package common + +import "log" + +// Logger define the way to receive logs from Consensus instance. +// NOTE: parameter in 'ctx' should be paired as key-value mapping. For example, +// to log an error with message: +// logger.Error("some message", "error", err) +// which is similar to loggers with context: +// logger.Error("some message", map[string]interface{}{ +// "error": err, +// }) +type Logger interface { + // Info logs info level logs. + Debug(msg string, ctx ...interface{}) + Info(msg string, ctx ...interface{}) + Warn(msg string, ctx ...interface{}) + Error(msg string, ctx ...interface{}) +} + +// NullLogger logs nothing. +type NullLogger struct{} + +// Debug implements Logger interface. +func (logger *NullLogger) Debug(msg string, ctx ...interface{}) { +} + +// Info implements Logger interface. +func (logger *NullLogger) Info(msg string, ctx ...interface{}) { +} + +// Warn implements Logger interface. +func (logger *NullLogger) Warn(msg string, ctx ...interface{}) { +} + +// Error implements Logger interface. +func (logger *NullLogger) Error(msg string, ctx ...interface{}) { +} + +// SimpleLogger logs everything. +type SimpleLogger struct{} + +// composeVargs makes (msg, ctx...) could be pass to log.Println +func composeVargs(msg string, ctxs []interface{}) []interface{} { + args := []interface{}{msg} + for _, c := range ctxs { + args = append(args, c) + } + return args +} + +// Debug implements Logger interface. +func (logger *SimpleLogger) Debug(msg string, ctx ...interface{}) { + log.Println(composeVargs(msg, ctx)...) +} + +// Info implements Logger interface. +func (logger *SimpleLogger) Info(msg string, ctx ...interface{}) { + log.Println(composeVargs(msg, ctx)...) +} + +// Warn implements Logger interface. +func (logger *SimpleLogger) Warn(msg string, ctx ...interface{}) { + log.Println(composeVargs(msg, ctx)...) +} + +// Error implements Logger interface. +func (logger *SimpleLogger) Error(msg string, ctx ...interface{}) { + log.Println(composeVargs(msg, ctx)...) +} diff --git a/core/configuration-chain.go b/core/configuration-chain.go index c40d788..8834e0d 100644 --- a/core/configuration-chain.go +++ b/core/configuration-chain.go @@ -19,7 +19,6 @@ package core import ( "fmt" - "log" "sync" "time" @@ -43,6 +42,7 @@ type configurationChain struct { recv dkgReceiver gov Governance dkg *dkgProtocol + logger common.Logger dkgLock sync.RWMutex dkgSigner map[uint64]*dkgShareSecret gpk map[uint64]*DKGGroupPublicKey @@ -58,11 +58,13 @@ type configurationChain struct { func newConfigurationChain( ID types.NodeID, recv dkgReceiver, - gov Governance) *configurationChain { + gov Governance, + logger common.Logger) *configurationChain { return &configurationChain{ ID: ID, recv: recv, gov: gov, + logger: logger, dkgSigner: make(map[uint64]*dkgShareSecret), gpk: make(map[uint64]*DKGGroupPublicKey), tsig: make(map[common.Hash]*tsigProtocol), @@ -101,6 +103,7 @@ func (cc *configurationChain) runDKG(round uint64) error { <-ticker.Tick() cc.dkgLock.Lock() // Phase 2(T = 0): Exchange DKG secret key share. + cc.logger.Debug("Calling Governance.DKGMasterPublicKeys", "round", round) cc.dkg.processMasterPublicKeys(cc.gov.DKGMasterPublicKeys(round)) // Phase 3(T = 0~λ): Propose complaint. // Propose complaint is done in `processMasterPublicKeys`. @@ -113,6 +116,7 @@ func (cc *configurationChain) runDKG(round uint64) error { <-ticker.Tick() cc.dkgLock.Lock() // Phase 5(T = 2λ): Propose Anti nack complaint. + cc.logger.Debug("Calling Governance.DKGComplaints", "round", round) cc.dkg.processNackComplaints(cc.gov.DKGComplaints(round)) cc.dkgLock.Unlock() <-ticker.Tick() @@ -123,6 +127,7 @@ func (cc *configurationChain) runDKG(round uint64) error { <-ticker.Tick() cc.dkgLock.Lock() // Phase 7(T = 4λ): Enforce complaints and nack complaints. + cc.logger.Debug("Calling Governance.DKGComplaints", "round", round) cc.dkg.enforceNackComplaints(cc.gov.DKGComplaints(round)) // Enforce complaint is done in `processPrivateShare`. // Phase 8(T = 5λ): DKG finalize. @@ -136,10 +141,14 @@ func (cc *configurationChain) runDKG(round uint64) error { cc.dkgLock.Lock() // Normally, IsDKGFinal would return true here. Use this for in case of // unexpected network fluctuation and ensure the robustness of DKG protocol. + cc.logger.Debug("Calling Governance.IsDKGFinal", "round", round) for !cc.gov.IsDKGFinal(round) { - log.Printf("[%s] DKG is not ready yet. Try again later...\n", cc.ID) + cc.logger.Info("DKG is not ready yet. Try again later...", + "nodeID", cc.ID) time.Sleep(500 * time.Millisecond) } + cc.logger.Debug("Calling Governance.DKGMasterPublicKeys", "round", round) + cc.logger.Debug("Calling Governance.DKGComplaints", "round", round) gpk, err := NewDKGGroupPublicKey(round, cc.gov.DKGMasterPublicKeys(round), cc.gov.DKGComplaints(round), @@ -155,8 +164,11 @@ func (cc *configurationChain) runDKG(round uint64) error { for nID := range gpk.qualifyNodeIDs { qualifies += fmt.Sprintf("%s ", nID.String()[:6]) } - log.Printf("[%s] Qualify Nodes(%d): (%d) %s\n", - cc.ID, round, len(gpk.qualifyIDs), qualifies) + cc.logger.Info("Qualify Nodes", + "nodeID", cc.ID, + "round", round, + "count", len(gpk.qualifyIDs), + "qualifies", qualifies) cc.dkgResult.Lock() defer cc.dkgResult.Unlock() cc.dkgSigner[round] = signer @@ -214,7 +226,9 @@ func (cc *configurationChain) runTSig( go func() { for _, psig := range pendingPsig { if err := cc.processPartialSignature(psig); err != nil { - log.Printf("[%s] %s", cc.ID, err) + cc.logger.Error("failed to process partial signature", + "nodeID", cc.ID, + "error", err) } } }() @@ -240,14 +254,20 @@ func (cc *configurationChain) runBlockTSig( if err != nil { return crypto.Signature{}, err } - log.Printf("[%s] Block TSIG(%d): %s\n", cc.ID, round, sig) + cc.logger.Info("Block TSIG", + "nodeID", cc.ID, + "round", round, + "signature", sig) return sig, nil } func (cc *configurationChain) runCRSTSig( round uint64, crs common.Hash) ([]byte, error) { sig, err := cc.runTSig(round, crs) - log.Printf("[%s] CRS(%d): %s\n", cc.ID, round+1, sig) + cc.logger.Info("CRS", + "nodeID", cc.ID, + "round", round+1, + "signature", sig) return sig.Signature[:], err } diff --git a/core/configuration-chain_test.go b/core/configuration-chain_test.go index 4d104ae..19d50a3 100644 --- a/core/configuration-chain_test.go +++ b/core/configuration-chain_test.go @@ -168,7 +168,8 @@ func (s *ConfigurationChainTestSuite) runDKG( for _, nID := range s.nIDs { gov, err := test.NewGovernance(0, 50*time.Millisecond) s.Require().NoError(err) - cfgChains[nID] = newConfigurationChain(nID, recv, gov) + cfgChains[nID] = newConfigurationChain( + nID, recv, gov, &common.NullLogger{}) recv.nodes[nID] = cfgChains[nID] recv.govs[nID] = gov } diff --git a/core/consensus.go b/core/consensus.go index 05e3301..2f46ec1 100644 --- a/core/consensus.go +++ b/core/consensus.go @@ -20,7 +20,6 @@ package core import ( "context" "fmt" - "log" "sync" "time" @@ -42,8 +41,6 @@ var ( "genesis block should be empty") ErrUnknownBlockProposed = fmt.Errorf( "unknown block is proposed") - ErrUnknownBlockConfirmed = fmt.Errorf( - "unknown block is confirmed") ErrIncorrectAgreementResultPosition = fmt.Errorf( "incorrect agreement result position") ErrNotEnoughVotes = fmt.Errorf( @@ -67,14 +64,16 @@ type consensusBAReceiver struct { func (recv *consensusBAReceiver) ProposeVote(vote *types.Vote) { if err := recv.agreementModule.prepareVote(vote); err != nil { - log.Println(err) + recv.consensus.logger.Error("Failed to prepare vote", "error", err) return } go func() { if err := recv.agreementModule.processVote(vote); err != nil { - log.Println(err) + recv.consensus.logger.Error("Failed to process vote", "error", err) return } + recv.consensus.logger.Debug("Calling Network.BroadcastVote", + "vote", vote) recv.consensus.network.BroadcastVote(vote) }() } @@ -83,9 +82,10 @@ func (recv *consensusBAReceiver) ProposeBlock() common.Hash { block := recv.consensus.proposeBlock(recv.chainID, recv.round) recv.consensus.baModules[recv.chainID].addCandidateBlock(block) if err := recv.consensus.preProcessBlock(block); err != nil { - log.Println(err) + recv.consensus.logger.Error("Failed to pre-process block", "error", err) return common.Hash{} } + recv.consensus.logger.Debug("Calling Network.BroadcastBlock", "block", block) recv.consensus.network.BroadcastBlock(block) return block.Hash } @@ -95,7 +95,7 @@ func (recv *consensusBAReceiver) ConfirmBlock( block, exist := recv.consensus.baModules[recv.chainID]. findCandidateBlock(hash) if !exist { - log.Println(ErrUnknownBlockConfirmed, hash) + recv.consensus.logger.Error("Unknown block confirmed", "hash", hash) return } recv.consensus.ccModule.registerBlock(block) @@ -103,13 +103,16 @@ func (recv *consensusBAReceiver) ConfirmBlock( for _, vote := range votes { voteList = append(voteList, *vote) } - recv.consensus.network.BroadcastAgreementResult(&types.AgreementResult{ + result := &types.AgreementResult{ BlockHash: hash, Position: block.Position, Votes: voteList, - }) + } + recv.consensus.logger.Debug("Calling Network.BroadcastAgreementResult", + "result", result) + recv.consensus.network.BroadcastAgreementResult(result) if err := recv.consensus.processBlock(block); err != nil { - log.Println(err) + recv.consensus.logger.Error("Failed to process block", "error", err) return } if block.Timestamp.After(recv.changeNotaryTime) { @@ -127,15 +130,18 @@ type consensusDKGReceiver struct { authModule *Authenticator nodeSetCache *NodeSetCache network Network + logger common.Logger } // ProposeDKGComplaint proposes a DKGComplaint. func (recv *consensusDKGReceiver) ProposeDKGComplaint( complaint *types.DKGComplaint) { if err := recv.authModule.SignDKGComplaint(complaint); err != nil { - log.Println(err) + recv.logger.Error("Failed to sign DKG complaint", "error", err) return } + recv.logger.Debug("Calling Governace.AddDKGComplaint", + "complaint", complaint) recv.gov.AddDKGComplaint(complaint.Round, complaint) } @@ -143,9 +149,10 @@ func (recv *consensusDKGReceiver) ProposeDKGComplaint( func (recv *consensusDKGReceiver) ProposeDKGMasterPublicKey( mpk *types.DKGMasterPublicKey) { if err := recv.authModule.SignDKGMasterPublicKey(mpk); err != nil { - log.Println(err) + recv.logger.Error("Failed to sign DKG master public key", "error", err) return } + recv.logger.Debug("Calling Governance.AddDKGMasterPublicKey", "key", mpk) recv.gov.AddDKGMasterPublicKey(mpk.Round, mpk) } @@ -153,14 +160,17 @@ func (recv *consensusDKGReceiver) ProposeDKGMasterPublicKey( func (recv *consensusDKGReceiver) ProposeDKGPrivateShare( prv *types.DKGPrivateShare) { if err := recv.authModule.SignDKGPrivateShare(prv); err != nil { - log.Println(err) + recv.logger.Error("Failed to sign DKG private share", "error", err) return } receiverPubKey, exists := recv.nodeSetCache.GetPublicKey(prv.ReceiverID) if !exists { - log.Println("public key for receiver not found") + recv.logger.Error("Public key for receiver not found", + "receiver", prv.ReceiverID.String()[:6]) return } + recv.logger.Debug("Calling Network.SendDKGPrivateShare", + "receiver", string(receiverPubKey.Bytes())) recv.network.SendDKGPrivateShare(receiverPubKey, prv) } @@ -169,19 +179,21 @@ func (recv *consensusDKGReceiver) ProposeDKGAntiNackComplaint( prv *types.DKGPrivateShare) { if prv.ProposerID == recv.ID { if err := recv.authModule.SignDKGPrivateShare(prv); err != nil { - log.Println(err) + recv.logger.Error("Failed sign DKG private share", "error", err) return } } + recv.logger.Debug("Calling Network.BroadcastDKGPrivateShare", "share", prv) recv.network.BroadcastDKGPrivateShare(prv) } // ProposeDKGFinalize propose a DKGFinalize message. func (recv *consensusDKGReceiver) ProposeDKGFinalize(final *types.DKGFinalize) { if err := recv.authModule.SignDKGFinalize(final); err != nil { - log.Println(err) + recv.logger.Error("Faield to sign DKG finalize", "error", err) return } + recv.logger.Debug("Calling Governance.AddDKGFinalize", "final", final) recv.gov.AddDKGFinalize(final.Round, final) } @@ -222,6 +234,7 @@ type Consensus struct { ctx context.Context ctxCancel context.CancelFunc event *common.Event + logger common.Logger } // NewConsensus construct an Consensus instance. @@ -231,14 +244,17 @@ func NewConsensus( gov Governance, db blockdb.BlockDatabase, network Network, - prv crypto.PrivateKey) *Consensus { + prv crypto.PrivateKey, + logger common.Logger) *Consensus { // TODO(w): load latest blockHeight from DB, and use config at that height. var ( round uint64 ) + logger.Debug("Calling Governance.Configuration", "round", round) config := gov.Configuration(round) nodeSetCache := NewNodeSetCache(gov) + logger.Debug("Calling Governance.CRS", "round", round) crs := gov.CRS(round) // Setup acking by information returned from Governace. nodes, err := nodeSetCache.GetNodeSet(round) @@ -252,7 +268,8 @@ func NewConsensus( // Setup nonblocking module. nbModule := newNonBlocking(app, debugApp) // Init lattice. - lattice := NewLattice(dMoment, config, authModule, nbModule, nbModule, db) + lattice := NewLattice( + dMoment, config, authModule, nbModule, nbModule, db, logger) // Init configuration chain. ID := types.NewNodeID(prv.PublicKey()) cfgModule := newConfigurationChain( @@ -263,8 +280,10 @@ func NewConsensus( authModule: authModule, nodeSetCache: nodeSetCache, network: network, + logger: logger, }, - gov) + gov, + logger) // Construct Consensus instance. con := &Consensus{ ID: ID, @@ -282,6 +301,7 @@ func NewConsensus( nodeSetCache: nodeSetCache, authModule: authModule, event: common.NewEvent(), + logger: logger, } con.baModules = make([]*agreement, config.NumChains) @@ -316,11 +336,13 @@ func (con *Consensus) Run(initBlock *types.Block) { con.ccModule.init(initBlock) // TODO(jimmy-dexon): change AppendConfig to add config for specific round. for i := uint64(0); i < initBlock.Position.Round; i++ { + con.logger.Debug("Calling Governance.Configuration", "round", i+1) cfg := con.gov.Configuration(i + 1) if err := con.lattice.AppendConfig(i+1, cfg); err != nil { panic(err) } } + con.logger.Debug("Calling Network.ReceiveChan") go con.processMsg(con.network.ReceiveChan()) con.cfgModule.registerDKG(con.round, int(con.currentConfig.DKGSetSize)/3+1) con.event.RegisterTime(con.dMoment.Add(con.currentConfig.RoundInterval/4), @@ -328,6 +350,7 @@ func (con *Consensus) Run(initBlock *types.Block) { con.runDKGTSIG(con.round) }) round1 := uint64(1) + con.logger.Debug("Calling Governance.Configuration", "round", round1) con.lattice.AppendConfig(round1, con.gov.Configuration(round1)) con.initialRound(con.dMoment) ticks := make([]chan struct{}, 0, con.currentConfig.NumChains) @@ -372,6 +395,9 @@ BALoop: if err != nil { panic(err) } + con.logger.Debug("Calling Governance.Configuration", + "round", recv.round) + con.logger.Debug("Calling Governance.CRS", "round", recv.round) nIDs = nodes.GetSubSet( int(con.gov.Configuration(recv.round).NotarySetSize), types.NewNotarySetTarget(con.gov.CRS(recv.round), chainID)) @@ -383,7 +409,9 @@ BALoop: } err := agreement.nextState() if err != nil { - log.Printf("[%s] %s\n", con.ID.String(), err) + con.logger.Error("Failed to proceed to next state", + "nodeID", con.ID.String(), + "error", err) break BALoop } for i := 0; i < agreement.clocks(); i++ { @@ -420,8 +448,8 @@ func (con *Consensus) runDKGTSIG(round uint64) { DKGTime := time.Now().Sub(startTime) if DKGTime.Nanoseconds() >= con.currentConfig.RoundInterval.Nanoseconds()/2 { - log.Printf("[%s] WARNING!!! Your computer cannot finish DKG on time!\n", - con.ID) + con.logger.Warn("Your computer cannot finish DKG on time!", + "nodeID", con.ID.String()) } }() if err := con.cfgModule.runDKG(round); err != nil { @@ -431,6 +459,7 @@ func (con *Consensus) runDKGTSIG(round uint64) { if err != nil { panic(err) } + con.logger.Debug("Calling Governance.Configuration", "round", round) hash := HashConfigurationBlock( nodes.IDs, con.gov.Configuration(round), @@ -447,6 +476,10 @@ func (con *Consensus) runDKGTSIG(round uint64) { if err = con.cfgModule.processPartialSignature(psig); err != nil { panic(err) } + con.logger.Debug("Calling Network.BroadcastDKGPartialSignature", + "proposer", psig.ProposerID, + "round", psig.Round, + "hash", psig.Hash) con.network.BroadcastDKGPartialSignature(psig) if _, err = con.cfgModule.runBlockTSig(round, hash); err != nil { panic(err) @@ -456,20 +489,29 @@ func (con *Consensus) runDKGTSIG(round uint64) { func (con *Consensus) runCRS() { // Start running next round CRS. + con.logger.Debug("Calling Governance.CRS", "round", con.round) psig, err := con.cfgModule.preparePartialSignature( con.round, con.gov.CRS(con.round)) if err != nil { - log.Println(err) + con.logger.Error("Failed to prepare partial signature", "error", err) } else if err = con.authModule.SignDKGPartialSignature(psig); err != nil { - log.Println(err) + con.logger.Error("Failed to sign DKG partial signature", "error", err) } else if err = con.cfgModule.processPartialSignature(psig); err != nil { - log.Println(err) + con.logger.Error("Failed to process partial signature", "error", err) } else { + con.logger.Debug("Calling Network.BroadcastDKGPartialSignature", + "proposer", psig.ProposerID, + "round", psig.Round, + "hash", psig.Hash) con.network.BroadcastDKGPartialSignature(psig) + con.logger.Debug("Calling Governance.CRS", "round", con.round) crs, err := con.cfgModule.runCRSTSig(con.round, con.gov.CRS(con.round)) if err != nil { - log.Println(err) + con.logger.Error("Failed to run CRS Tsig", "error", err) } else { + con.logger.Debug("Calling Governance.ProposeCRS", + "round", con.round, + "crs", crs) con.gov.ProposeCRS(crs) } } @@ -481,6 +523,7 @@ func (con *Consensus) initialRound(startTime time.Time) { return default: } + con.logger.Debug("Calling Governance.Configuration", "round", con.round) con.currentConfig = con.gov.Configuration(con.round) con.event.RegisterTime(startTime.Add(con.currentConfig.RoundInterval/2), @@ -532,33 +575,40 @@ func (con *Consensus) processMsg(msgChan <-chan interface{}) { // For sync mode. if val.IsFinalized() { if err := con.processFinalizedBlock(val); err != nil { - log.Println(err) + con.logger.Error("Failed to process finalized block", + "error", err) } } else { if err := con.preProcessBlock(val); err != nil { - log.Println(err) + con.logger.Error("Failed to pre process block", + "error", err) } } case *types.Vote: if err := con.ProcessVote(val); err != nil { - log.Println(err) + con.logger.Error("Failed to process vote", + "error", err) } case *types.AgreementResult: if err := con.ProcessAgreementResult(val); err != nil { - log.Println(err) + con.logger.Error("Failed to process agreement result", + "error", err) } case *types.BlockRandomnessResult: if err := con.ProcessBlockRandomnessResult(val); err != nil { - log.Println(err) + con.logger.Error("Failed to process block randomness result", + "error", err) } case *types.DKGPrivateShare: if err := con.cfgModule.processPrivateShare(val); err != nil { - log.Println(err) + con.logger.Error("Failed to process private share", + "error", err) } case *types.DKGPartialSignature: if err := con.cfgModule.processPartialSignature(val); err != nil { - log.Println(err) + con.logger.Error("Failed to process partial signature", + "error", err) } } } @@ -572,7 +622,7 @@ func (con *Consensus) proposeBlock(chainID uint32, round uint64) *types.Block { }, } if err := con.prepareBlock(block, time.Now().UTC()); err != nil { - log.Println(err) + con.logger.Error("Failed to prepare block", "error", err) return nil } return block @@ -624,6 +674,7 @@ func (con *Consensus) ProcessAgreementResult( if !con.cfgModule.touchTSigHash(rand.BlockHash) { return nil } + con.logger.Debug("Calling Network.BroadcastAgreementResult", "result", rand) con.network.BroadcastAgreementResult(rand) dkgSet, err := con.nodeSetCache.GetDKGSet(rand.Position.Round) if err != nil { @@ -642,12 +693,16 @@ func (con *Consensus) ProcessAgreementResult( if err = con.cfgModule.processPartialSignature(psig); err != nil { return err } + con.logger.Debug("Calling Network.BroadcastDKGPartialSignature", + "proposer", psig.ProposerID, + "round", psig.Round, + "hash", psig.Hash) con.network.BroadcastDKGPartialSignature(psig) go func() { tsig, err := con.cfgModule.runTSig(rand.Position.Round, rand.BlockHash) if err != nil { if err != ErrTSigAlreadyRunning { - log.Println(err) + con.logger.Error("Faield to run TSIG", "error", err) } return } @@ -657,9 +712,14 @@ func (con *Consensus) ProcessAgreementResult( Randomness: tsig.Signature, } if err := con.ProcessBlockRandomnessResult(result); err != nil { - log.Println(err) + con.logger.Error("Failed to process randomness result", + "error", err) return } + con.logger.Debug("Calling Network.BroadcastRandomnessResult", + "hash", result.BlockHash, + "position", result.Position, + "randomness", string(result.Randomness)) con.network.BroadcastRandomnessResult(result) }() return nil @@ -676,6 +736,10 @@ func (con *Consensus) ProcessBlockRandomnessResult( } // TODO(jimmy-dexon): reuse the GPK. round := rand.Position.Round + con.logger.Debug("Calling Governance.DKGMasterPublicKeys", + "round", con.round) + con.logger.Debug("Calling Governance.DKGComplaints", "round", con.round) + con.logger.Debug("Calling Governance.Configuration", "round", con.round) gpk, err := NewDKGGroupPublicKey(round, con.gov.DKGMasterPublicKeys(round), con.gov.DKGComplaints(round), @@ -687,6 +751,10 @@ func (con *Consensus) ProcessBlockRandomnessResult( rand.BlockHash, crypto.Signature{Signature: rand.Randomness}) { return ErrIncorrectBlockRandomnessResult } + con.logger.Debug("Calling Network.BroadcastRandomnessResult", + "hash", rand.BlockHash, + "position", rand.Position, + "randomness", string(rand.Randomness)) con.network.BroadcastRandomnessResult(rand) if err := con.ccModule.processBlockRandomnessResult(rand); err != nil { if err != ErrBlockNotRegistered { @@ -734,6 +802,8 @@ func (con *Consensus) processBlock(block *types.Block) (err error) { } if b.Position.Round > con.round { con.round++ + con.logger.Debug("Calling Governance.Configuration", + "round", con.round+1) con.lattice.AppendConfig(con.round+1, con.gov.Configuration(con.round+1)) } // TODO(mission): clone types.FinalizationResult @@ -780,6 +850,7 @@ func (con *Consensus) prepareBlock(b *types.Block, } // TODO(mission): decide CRS by block's round, which could be determined by // block's info (ex. position, timestamp). + con.logger.Debug("Calling Governance.CRS", "round", 0) if err = con.authModule.SignCRS(b, con.gov.CRS(0)); err != nil { return } diff --git a/core/consensus_test.go b/core/consensus_test.go index ed1658f..bfe01da 100644 --- a/core/consensus_test.go +++ b/core/consensus_test.go @@ -168,8 +168,8 @@ func (s *ConsensusTestSuite) prepareConsensus( s.Require().Nil(err) nID := types.NewNodeID(prvKey.PublicKey()) network := conn.newNetwork(nID) - con := NewConsensus(dMoment, app, gov, db, - network, prvKey) + con := NewConsensus( + dMoment, app, gov, db, network, prvKey, &common.NullLogger{}) con.ccModule.init(&types.Block{}) conn.setCon(nID, con) return app, con diff --git a/core/lattice.go b/core/lattice.go index e6f9848..73fdcb0 100644 --- a/core/lattice.go +++ b/core/lattice.go @@ -37,6 +37,7 @@ type Lattice struct { data *latticeData toModule *totalOrdering ctModule *consensusTimestamp + logger common.Logger } // NewLattice constructs an Lattice instance. @@ -46,7 +47,8 @@ func NewLattice( authModule *Authenticator, app Application, debug Debug, - db blockdb.BlockDatabase) (s *Lattice) { + db blockdb.BlockDatabase, + logger common.Logger) (s *Lattice) { // Create genesis latticeDataConfig. dataConfig := newGenesisLatticeDataConfig(dMoment, cfg) toConfig := newGenesisTotalOrderingConfig(dMoment, cfg) @@ -59,6 +61,7 @@ func NewLattice( data: newLatticeData(db, dataConfig), toModule: newTotalOrdering(toConfig), ctModule: newConsensusTimestamp(dMoment, 0, cfg.NumChains), + logger: logger, } return } @@ -74,9 +77,12 @@ func (s *Lattice) PrepareBlock( if err = s.data.prepareBlock(b); err != nil { return } + s.logger.Debug("Calling Application.PreparePayload", "position", b.Position) if b.Payload, err = s.app.PreparePayload(b.Position); err != nil { return } + s.logger.Debug("Calling Application.PrepareWitness", + "height", b.Witness.Height) if b.Witness, err = s.app.PrepareWitness(b.Witness.Height); err != nil { return } @@ -107,6 +113,7 @@ func (s *Lattice) SanityCheck(b *types.Block, checkRelation bool) (err error) { } } // Verify data in application layer. + s.logger.Debug("Calling Application.VerifyBlock", "block", b) if !s.app.VerifyBlock(b) { err = ErrInvalidBlock return err @@ -122,6 +129,7 @@ func (s *Lattice) SanityCheck(b *types.Block, checkRelation bool) (err error) { if err == ErrAckingBlockNotExists { s.pool.addBlock(b) } + s.logger.Error("Sanity Check failed", "error", err) return } return @@ -146,6 +154,7 @@ func (s *Lattice) ProcessBlock( if inLattice, err = s.data.addBlock(input); err != nil { // TODO(mission): if sanity check failed with "acking block doesn't // exists", we should keep it in a pool. + s.logger.Error("Sanity Check failed when adding blocks", "error", err) return } // TODO(mission): remove this hack, BA related stuffs should not @@ -153,6 +162,7 @@ func (s *Lattice) ProcessBlock( if s.debug != nil { s.debug.StronglyAcked(input.Hash) } + s.logger.Debug("Calling Application.BlockConfirmed", "block", input) s.app.BlockConfirmed(*input.Clone()) // Purge blocks in pool with the same chainID and lower height. s.pool.purgeBlocks(input.Position.ChainID, input.Position.Height) diff --git a/core/lattice_test.go b/core/lattice_test.go index 5c06b92..a508f2b 100644 --- a/core/lattice_test.go +++ b/core/lattice_test.go @@ -121,7 +121,8 @@ func (s *LatticeTestSuite) newTestLatticeMgr( NewAuthenticator(prvKey), app, app, - db)} + db, + &common.NullLogger{})} } func (s *LatticeTestSuite) TestBasicUsage() { diff --git a/core/types/block-randomness.go b/core/types/block-randomness.go index b101e22..ebffd2b 100644 --- a/core/types/block-randomness.go +++ b/core/types/block-randomness.go @@ -18,6 +18,8 @@ package types import ( + "fmt" + "github.com/dexon-foundation/dexon-consensus-core/common" ) @@ -28,6 +30,11 @@ type AgreementResult struct { Votes []Vote `json:"votes"` } +func (r *AgreementResult) String() string { + return fmt.Sprintf( + "agreementResult[%s:%s]", r.BlockHash, &r.Position) +} + // BlockRandomnessResult describes a block randomness result type BlockRandomnessResult struct { BlockHash common.Hash `json:"block_hash"` diff --git a/core/types/dkg.go b/core/types/dkg.go index c13740b..6018ebd 100644 --- a/core/types/dkg.go +++ b/core/types/dkg.go @@ -53,6 +53,12 @@ type DKGMasterPublicKey struct { Signature crypto.Signature `json:"signature"` } +func (d *DKGMasterPublicKey) String() string { + return fmt.Sprintf("MasterPublicKey[%s:%d]", + d.ProposerID.String()[:6], + d.Round) +} + // NewDKGMasterPublicKey returns a new DKGMasterPublicKey instance. func NewDKGMasterPublicKey() *DKGMasterPublicKey { return &DKGMasterPublicKey{ @@ -75,6 +81,11 @@ type DKGComplaint struct { Signature crypto.Signature `json:"signature"` } +func (c *DKGComplaint) String() string { + return fmt.Sprintf("DKGComplaint[%s:%d]%s", + c.ProposerID.String()[:6], c.Round, &c.PrivateShare) +} + // DKGPartialSignature describe a partial signature in DKG protocol. type DKGPartialSignature struct { ProposerID NodeID `json:"proposer_id"` @@ -91,6 +102,12 @@ type DKGFinalize struct { Signature crypto.Signature `json:"signature"` } +func (final *DKGFinalize) String() string { + return fmt.Sprintf("DKGFinal[%s:%d]", + final.ProposerID.String()[:6], + final.Round) +} + // IsNack returns true if it's a nack complaint in DKG protocol. func (c *DKGComplaint) IsNack() bool { return len(c.PrivateShare.Signature.Signature) == 0 diff --git a/core/types/position.go b/core/types/position.go index 4e254ba..51de405 100644 --- a/core/types/position.go +++ b/core/types/position.go @@ -17,7 +17,10 @@ package types -import "errors" +import ( + "errors" + "fmt" +) // ErrComparePositionOnDifferentChains raised when attempting to // compare two positions with different chain ID. @@ -31,6 +34,10 @@ type Position struct { Height uint64 `json:"height"` } +func (pos *Position) String() string { + return fmt.Sprintf("pos[%d:%d:%d]", pos.ChainID, pos.Round, pos.Height) +} + // Equal checks if two positions are equal, it panics when their chainIDs // are different. func (pos *Position) Equal(other *Position) bool { diff --git a/integration_test/node.go b/integration_test/node.go index 09d1557..b6704e8 100644 --- a/integration_test/node.go +++ b/integration_test/node.go @@ -121,7 +121,8 @@ func NewNode( core.NewAuthenticator(privateKey), app, app, - db), + db, + &common.NullLogger{}), } } diff --git a/simulation/node.go b/simulation/node.go index 0a59994..5919b3e 100644 --- a/simulation/node.go +++ b/simulation/node.go @@ -100,7 +100,13 @@ func (n *node) run(serverEndpoint interface{}, dMoment time.Time) { } } n.consensus = core.NewConsensus( - dMoment, n.app, n.gov, n.db, n.netModule, n.prvKey) + dMoment, + n.app, + n.gov, + n.db, + n.netModule, + n.prvKey, + &common.SimpleLogger{}) go n.consensus.Run(&types.Block{}) // Blocks forever. |