Fixup: for debugging

3 files changed, 29 insertions, 6 deletions

diff --git a/core/agreement-mgr.go b/core/agreement-mgr.go
index 608fcac..2617564 100644
--- a/core/agreement-mgr.go
+++ b/core/agreement-mgr.go
@@ -228,9 +228,14 @@ func (mgr *agreementMgr) appendConfig(
 }
 
 func (mgr *agreementMgr) processVote(v *types.Vote) error {
+	mgr.logger.Debug("process vote", "vote", v)
+	defer func() {
+		mgr.logger.Debug("vote processing finished", "vote", v)
+	}()
 	mgr.chainLock.RLock()
 	defer mgr.chainLock.RUnlock()
 	signals, err := mgr.vCache.ProcessVote(v)
+	mgr.logger.Debug("vote processed", "vote", v, "error", err, "signals", len(signals))
 	if err != nil || len(signals) == 0 {
 		return err
 	}
diff --git a/core/agreement.go b/core/agreement.go
index 7b3a464..e26361b 100644
--- a/core/agreement.go
+++ b/core/agreement.go
@@ -154,6 +154,7 @@ func newAgreement(
 // restart the agreement
 func (a *agreement) restart(
 	aID types.Position, leader types.NodeID, crs common.Hash) {
+	a.logger.Trace("restart agreement", "pos", &aID, "leader", leader.String()[:6], "crs", crs.String()[:6])
 	if !func() bool {
 		a.lock.Lock()
 		defer a.lock.Unlock()
diff --git a/integration_test/consensus_test.go b/integration_test/consensus_test.go
index 7ca3f66..6cccffd 100644
--- a/integration_test/consensus_test.go
+++ b/integration_test/consensus_test.go
@@ -20,6 +20,8 @@ package integration
 import (
 	"context"
 	"fmt"
+	"io"
+	"os"
 	"sync"
 	"testing"
 	"time"
@@ -32,9 +34,24 @@ import (
 	"github.com/dexon-foundation/dexon-consensus/core/test"
 	"github.com/dexon-foundation/dexon-consensus/core/types"
 	"github.com/dexon-foundation/dexon-consensus/core/utils"
+	"github.com/ethereum/go-ethereum/log"
 	"github.com/stretchr/testify/suite"
 )
 
+func newLogger(logPrefix string) common.Logger {
+	mw := io.Writer(os.Stderr)
+	if logPrefix != "" {
+		f, err := os.Create(logPrefix + ".log")
+		if err != nil {
+			panic(err)
+		}
+		mw = io.MultiWriter(f)
+	}
+	logger := log.New()
+	logger.SetHandler(log.StreamHandler(mw, log.TerminalFormat(false)))
+	return logger
+}
+
 // There is no scheduler in these tests, we need to wait a long period to make
 // sure these tests are ok.
 type ConsensusTestSuite struct {
@@ -100,7 +117,7 @@ func (s *ConsensusTestSuite) setupNodes(
 			node.db,
 			node.network,
 			k,
-			&common.NullLogger{},
+			newLogger(node.ID.String()[:6]),
 		)
 	}
 	return nodes
@@ -189,7 +206,7 @@ func (s *ConsensusTestSuite) syncBlocksWithSomeNode(
 	return
 }
 
-func (s *ConsensusTestSuite) TestSimple() {
+func (s *ConsensusTestSuite) _TestSimple() {
 	// The simplest test case:
 	//  - Node set is equals to DKG set and notary set for each chain in each
 	//    round.
@@ -238,7 +255,7 @@ Loop:
 	s.verifyNodes(nodes)
 }
 
-func (s *ConsensusTestSuite) TestNumChainsChange() {
+func (s *ConsensusTestSuite) _TestNumChainsChange() {
 	var (
 		req        = s.Require()
 		peerCount  = 4
@@ -342,10 +359,10 @@ func (s *ConsensusTestSuite) TestSync() {
 	req.NoError(seedGov.State().RequestChange(
 		test.StateChangeRoundInterval, 55*time.Second))
 	req.NoError(seedGov.State().RequestChange(
-		test.StateChangeNumChains, uint32(5)))
+		test.StateChangeNumChains, uint32(7)))
 	seedGov.CatchUpWithRound(0)
 	req.NoError(seedGov.State().RequestChange(
-		test.StateChangeNumChains, uint32(4)))
+		test.StateChangeNumChains, uint32(6)))
 	seedGov.CatchUpWithRound(1)
 	// A short round interval.
 	nodes := s.setupNodes(dMoment, prvKeys, seedGov)
@@ -401,7 +418,7 @@ ReachAlive:
 		syncNode.db,
 		syncNode.network,
 		prvKeys[0],
-		&common.NullLogger{},
+		newLogger(syncNode.ID.String()[:6]+"-sync"),
 	)
 	// Initialize communication channel, it's not recommended to assertion in
 	// another go routine.