certusone
/
tendermint
mirror of https://github.com/certusone/tendermint.git
1
0
Fork 0
Code Issues Projects Releases Wiki Activity

Merge pull request #116 from tendermint/logger 

Logger
This commit is contained in:
Jae Kwon 2015-07-19 16:16:57 -07:00
parent 95765db7eb a28d924966
commit 111f001767
31 changed files with 258 additions and 238 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
Godeps/Godeps.json generated
View File

@ -72,8 +72,8 @@
},
{
"ImportPath": "github.com/tendermint/log15",
"Comment": "v2.3-33-g105a1be",
"Rev": "105a1beefe3379227a0d61733a29fd2c34f7080c"
"Comment": "v2.3-34-gbec7415",
"Rev": "bec7415fb62f05ac62298c2bc1a080d45ac3065c"
},
{
"ImportPath": "golang.org/x/crypto/curve25519",

4
Godeps/_workspace/src/github.com/tendermint/log15/format.go generated vendored
View File

@ -52,8 +52,10 @@ func TerminalFormat() Format {
color = 31
case LvlWarn:
color = 33
case LvlInfo:
case LvlNotice:
color = 32
case LvlInfo:
color = 34
case LvlDebug:
color = 36
}

10
Godeps/_workspace/src/github.com/tendermint/log15/logger.go generated vendored
View File

@ -17,6 +17,7 @@ const (
LvlCrit Lvl = iota
LvlError
LvlWarn
LvlNotice
LvlInfo
LvlDebug
)
@ -28,6 +29,8 @@ func (l Lvl) String() string {
return "dbug"
case LvlInfo:
return "info"
case LvlNotice:
return "notice"
case LvlWarn:
return "warn"
case LvlError:
@ -47,6 +50,8 @@ func LvlFromString(lvlString string) (Lvl, error) {
return LvlDebug, nil
case "info":
return LvlInfo, nil
case "notice":
return LvlNotice, nil
case "warn":
return LvlWarn, nil
case "error", "eror":
@ -85,6 +90,7 @@ type Logger interface {
// Log a message at the given level with context key/value pairs
Debug(msg string, ctx ...interface{})
Info(msg string, ctx ...interface{})
Notice(msg string, ctx ...interface{})
Warn(msg string, ctx ...interface{})
Error(msg string, ctx ...interface{})
Crit(msg string, ctx ...interface{})
@ -133,6 +139,10 @@ func (l *logger) Info(msg string, ctx ...interface{}) {
l.write(msg, LvlInfo, ctx)
}
func (l *logger) Notice(msg string, ctx ...interface{}) {
l.write(msg, LvlNotice, ctx)
}
func (l *logger) Warn(msg string, ctx ...interface{}) {
l.write(msg, LvlWarn, ctx)
}

5
Godeps/_workspace/src/github.com/tendermint/log15/root.go generated vendored
View File

@ -51,6 +51,11 @@ func Info(msg string, ctx ...interface{}) {
root.write(msg, LvlInfo, ctx)
}
// Notice is a convenient alias for Root().Notice
func Notice(msg string, ctx ...interface{}) {
root.write(msg, LvlNotice, ctx)
}
// Warn is a convenient alias for Root().Warn
func Warn(msg string, ctx ...interface{}) {
root.write(msg, LvlWarn, ctx)

2
Godeps/_workspace/src/github.com/tendermint/log15/syslog.go generated vendored
View File

@ -34,6 +34,8 @@ func sharedSyslog(fmtr Format, sysWr *syslog.Writer, err error) (Handler, error)
syslogFn = sysWr.Err
case LvlWarn:
syslogFn = sysWr.Warning
case LvlNotice:
syslogFn = sysWr.Notice
case LvlInfo:
syslogFn = sysWr.Info
case LvlDebug:

58
binary/reflect.go
View File

@ -260,7 +260,7 @@ func readReflectBinary(rv reflect.Value, rt reflect.Type, opts Options, r io.Rea
if *err != nil {
return
}
log.Debug("Read bytearray", "bytes", buf)
log.Info("Read bytearray", "bytes", buf)
reflect.Copy(rv, reflect.ValueOf(buf))
} else {
for i := 0; i < length; i++ {
@ -274,7 +274,7 @@ func readReflectBinary(rv reflect.Value, rt reflect.Type, opts Options, r io.Rea
return
}
}
log.Debug(Fmt("Read %v-array", elemRt), "length", length)
log.Info(Fmt("Read %v-array", elemRt), "length", length)
}
case reflect.Slice:
@ -282,13 +282,13 @@ func readReflectBinary(rv reflect.Value, rt reflect.Type, opts Options, r io.Rea
if elemRt.Kind() == reflect.Uint8 {
// Special case: Byteslices
byteslice := ReadByteSlice(r, n, err)
log.Debug("Read byteslice", "bytes", byteslice)
log.Info("Read byteslice", "bytes", byteslice)
rv.Set(reflect.ValueOf(byteslice))
} else {
var sliceRv reflect.Value
// Read length
length := ReadVarint(r, n, err)
log.Debug(Fmt("Read length: %v", length))
log.Info(Fmt("Read length: %v", length))
sliceRv = reflect.MakeSlice(rt, 0, 0)
// read one ReflectSliceChunk at a time and append
for i := 0; i*ReflectSliceChunk < length; i++ {
@ -315,7 +315,7 @@ func readReflectBinary(rv reflect.Value, rt reflect.Type, opts Options, r io.Rea
if rt == timeType {
// Special case: time.Time
t := ReadTime(r, n, err)
log.Debug(Fmt("Read time: %v", t))
log.Info(Fmt("Read time: %v", t))
rv.Set(reflect.ValueOf(t))
} else {
for _, fieldInfo := range typeInfo.Fields {
@ -327,74 +327,74 @@ func readReflectBinary(rv reflect.Value, rt reflect.Type, opts Options, r io.Rea
case reflect.String:
str := ReadString(r, n, err)
log.Debug(Fmt("Read string: %v", str))
log.Info(Fmt("Read string: %v", str))
rv.SetString(str)
case reflect.Int64:
if opts.Varint {
num := ReadVarint(r, n, err)
log.Debug(Fmt("Read num: %v", num))
log.Info(Fmt("Read num: %v", num))
rv.SetInt(int64(num))
} else {
num := ReadInt64(r, n, err)
log.Debug(Fmt("Read num: %v", num))
log.Info(Fmt("Read num: %v", num))
rv.SetInt(int64(num))
}
case reflect.Int32:
num := ReadUint32(r, n, err)
log.Debug(Fmt("Read num: %v", num))
log.Info(Fmt("Read num: %v", num))
rv.SetInt(int64(num))
case reflect.Int16:
num := ReadUint16(r, n, err)
log.Debug(Fmt("Read num: %v", num))
log.Info(Fmt("Read num: %v", num))
rv.SetInt(int64(num))
case reflect.Int8:
num := ReadUint8(r, n, err)
log.Debug(Fmt("Read num: %v", num))
log.Info(Fmt("Read num: %v", num))
rv.SetInt(int64(num))
case reflect.Int:
num := ReadVarint(r, n, err)
log.Debug(Fmt("Read num: %v", num))
log.Info(Fmt("Read num: %v", num))
rv.SetInt(int64(num))
case reflect.Uint64:
if opts.Varint {
num := ReadVarint(r, n, err)
log.Debug(Fmt("Read num: %v", num))
log.Info(Fmt("Read num: %v", num))
rv.SetUint(uint64(num))
} else {
num := ReadUint64(r, n, err)
log.Debug(Fmt("Read num: %v", num))
log.Info(Fmt("Read num: %v", num))
rv.SetUint(uint64(num))
}
case reflect.Uint32:
num := ReadUint32(r, n, err)
log.Debug(Fmt("Read num: %v", num))
log.Info(Fmt("Read num: %v", num))
rv.SetUint(uint64(num))
case reflect.Uint16:
num := ReadUint16(r, n, err)
log.Debug(Fmt("Read num: %v", num))
log.Info(Fmt("Read num: %v", num))
rv.SetUint(uint64(num))
case reflect.Uint8:
num := ReadUint8(r, n, err)
log.Debug(Fmt("Read num: %v", num))
log.Info(Fmt("Read num: %v", num))
rv.SetUint(uint64(num))
case reflect.Uint:
num := ReadVarint(r, n, err)
log.Debug(Fmt("Read num: %v", num))
log.Info(Fmt("Read num: %v", num))
rv.SetUint(uint64(num))
case reflect.Bool:
num := ReadUint8(r, n, err)
log.Debug(Fmt("Read bool: %v", num))
log.Info(Fmt("Read bool: %v", num))
rv.SetBool(num > 0)
default:
@ -669,7 +669,7 @@ func readReflectJSON(rv reflect.Value, rt reflect.Type, o interface{}, err *erro
*err = errors.New(Fmt("Expected bytearray of length %v but got %v", length, len(buf)))
return
}
log.Debug("Read bytearray", "bytes", buf)
log.Info("Read bytearray", "bytes", buf)
reflect.Copy(rv, reflect.ValueOf(buf))
} else {
oSlice, ok := o.([]interface{})
@ -685,7 +685,7 @@ func readReflectJSON(rv reflect.Value, rt reflect.Type, o interface{}, err *erro
elemRv := rv.Index(i)
readReflectJSON(elemRv, elemRt, oSlice[i], err)
}
log.Debug(Fmt("Read %v-array", elemRt), "length", length)
log.Info(Fmt("Read %v-array", elemRt), "length", length)
}
case reflect.Slice:
@ -702,7 +702,7 @@ func readReflectJSON(rv reflect.Value, rt reflect.Type, o interface{}, err *erro
*err = err_
return
}
log.Debug("Read byteslice", "bytes", byteslice)
log.Info("Read byteslice", "bytes", byteslice)
rv.Set(reflect.ValueOf(byteslice))
} else {
// Read length
@ -712,7 +712,7 @@ func readReflectJSON(rv reflect.Value, rt reflect.Type, o interface{}, err *erro
return
}
length := len(oSlice)
log.Debug(Fmt("Read length: %v", length))
log.Info(Fmt("Read length: %v", length))
sliceRv := reflect.MakeSlice(rt, length, length)
// Read elems
for i := 0; i < length; i++ {
@ -730,7 +730,7 @@ func readReflectJSON(rv reflect.Value, rt reflect.Type, o interface{}, err *erro
*err = errors.New(Fmt("Expected string but got type %v", reflect.TypeOf(o)))
return
}
log.Debug(Fmt("Read time: %v", str))
log.Info(Fmt("Read time: %v", str))
t, err_ := time.Parse(rfc2822, str)
if err_ != nil {
*err = err_
@ -762,7 +762,7 @@ func readReflectJSON(rv reflect.Value, rt reflect.Type, o interface{}, err *erro
*err = errors.New(Fmt("Expected string but got type %v", reflect.TypeOf(o)))
return
}
log.Debug(Fmt("Read string: %v", str))
log.Info(Fmt("Read string: %v", str))
rv.SetString(str)
case reflect.Int64, reflect.Int32, reflect.Int16, reflect.Int8, reflect.Int:
@ -771,7 +771,7 @@ func readReflectJSON(rv reflect.Value, rt reflect.Type, o interface{}, err *erro
*err = errors.New(Fmt("Expected numeric but got type %v", reflect.TypeOf(o)))
return
}
log.Debug(Fmt("Read num: %v", num))
log.Info(Fmt("Read num: %v", num))
rv.SetInt(int64(num))
case reflect.Uint64, reflect.Uint32, reflect.Uint16, reflect.Uint8, reflect.Uint:
@ -784,7 +784,7 @@ func readReflectJSON(rv reflect.Value, rt reflect.Type, o interface{}, err *erro
*err = errors.New(Fmt("Expected unsigned numeric but got %v", num))
return
}
log.Debug(Fmt("Read num: %v", num))
log.Info(Fmt("Read num: %v", num))
rv.SetUint(uint64(num))
case reflect.Bool:
@ -793,7 +793,7 @@ func readReflectJSON(rv reflect.Value, rt reflect.Type, o interface{}, err *erro
*err = errors.New(Fmt("Expected boolean but got type %v", reflect.TypeOf(o)))
return
}
log.Debug(Fmt("Read boolean: %v", bl))
log.Info(Fmt("Read boolean: %v", bl))
rv.SetBool(bl)
default:
@ -803,7 +803,7 @@ func readReflectJSON(rv reflect.Value, rt reflect.Type, o interface{}, err *erro
}
func writeReflectJSON(rv reflect.Value, rt reflect.Type, w io.Writer, n *int64, err *error) {
log.Debug(Fmt("writeReflectJSON(%v, %v, %v, %v, %v)", rv, rt, w, n, err))
log.Info(Fmt("writeReflectJSON(%v, %v, %v, %v, %v)", rv, rt, w, n, err))
// Get typeInfo
typeInfo := GetTypeInfo(rt)

4
binary/reflect_test.go
View File

@ -356,7 +356,7 @@ func TestBinary(t *testing.T) {
for i, testCase := range testCases {
log.Info(fmt.Sprintf("Running test case %v", i))
log.Notice(fmt.Sprintf("Running test case %v", i))
// Construct an object
o := testCase.Constructor()
@ -398,7 +398,7 @@ func TestJSON(t *testing.T) {
for i, testCase := range testCases {
log.Info(fmt.Sprintf("Running test case %v", i))
log.Notice(fmt.Sprintf("Running test case %v", i))
// Construct an object
o := testCase.Constructor()

8
blockchain/pool.go
View File

@ -71,14 +71,14 @@ func NewBlockPool(start int, requestsCh chan<- BlockRequest, timeoutsCh chan<- s
func (pool *BlockPool) Start() {
if atomic.CompareAndSwapInt32(&pool.running, 0, 1) {
log.Info("Starting BlockPool")
log.Notice("Starting BlockPool")
go pool.run()
}
}
func (pool *BlockPool) Stop() {
if atomic.CompareAndSwapInt32(&pool.running, 1, 0) {
log.Info("Stopping BlockPool")
log.Notice("Stopping BlockPool")
pool.repeater.Stop()
}
}
@ -354,12 +354,12 @@ func requestRoutine(pool *BlockPool, height int) {
PICK_LOOP:
for {
if !pool.IsRunning() {
log.Debug("BlockPool not running. Stopping requestRoutine", "height", height)
log.Info("BlockPool not running. Stopping requestRoutine", "height", height)
return
}
peer = pool.pickIncrAvailablePeer(height)
if peer == nil {
//log.Debug("No peers available", "height", height)
//log.Info("No peers available", "height", height)
time.Sleep(requestIntervalMS * time.Millisecond)
continue PICK_LOOP
}

8
blockchain/pool_test.go
View File

@ -60,7 +60,7 @@ func TestBasic(t *testing.T) {
case peerId := <-timeoutsCh:
t.Errorf("timeout: %v", peerId)
case request := <-requestsCh:
log.Debug("TEST: Pulled new BlockRequest", "request", request)
log.Info("TEST: Pulled new BlockRequest", "request", request)
if request.Height == 300 {
return // Done!
}
@ -68,7 +68,7 @@ func TestBasic(t *testing.T) {
go func() {
block := &types.Block{Header: &types.Header{Height: request.Height}}
pool.AddBlock(block, request.PeerId)
log.Debug("TEST: Added block", "block", request.Height, "peer", request.PeerId)
log.Info("TEST: Added block", "block", request.Height, "peer", request.PeerId)
}()
}
}
@ -112,7 +112,7 @@ func TestTimeout(t *testing.T) {
for {
select {
case peerId := <-timeoutsCh:
log.Debug("Timeout", "peerId", peerId)
log.Info("Timeout", "peerId", peerId)
if _, ok := timedOut[peerId]; !ok {
counter++
if counter == len(peers) {
@ -120,7 +120,7 @@ func TestTimeout(t *testing.T) {
}
}
case request := <-requestsCh:
log.Debug("TEST: Pulled new BlockRequest", "request", request)
log.Info("TEST: Pulled new BlockRequest", "request", request)
}
}

14
blockchain/reactor.go
View File

@ -83,7 +83,7 @@ func NewBlockchainReactor(state *sm.State, store *BlockStore, sync bool) *Blockc
// Implements Reactor
func (bcR *BlockchainReactor) Start(sw *p2p.Switch) {
if atomic.CompareAndSwapUint32(&bcR.running, 0, 1) {
log.Info("Starting BlockchainReactor")
log.Notice("Starting BlockchainReactor")
bcR.sw = sw
if bcR.sync {
bcR.pool.Start()
@ -95,7 +95,7 @@ func (bcR *BlockchainReactor) Start(sw *p2p.Switch) {
// Implements Reactor
func (bcR *BlockchainReactor) Stop() {
if atomic.CompareAndSwapUint32(&bcR.running, 1, 0) {
log.Info("Stopping BlockchainReactor")
log.Notice("Stopping BlockchainReactor")
close(bcR.quit)
bcR.pool.Stop()
}
@ -132,7 +132,7 @@ func (bcR *BlockchainReactor) Receive(chId byte, src *p2p.Peer, msgBytes []byte)
return
}
log.Info("Received message", "msg", msg)
log.Notice("Received message", "msg", msg)
switch msg := msg.(type) {
case *bcBlockRequestMessage:
@ -201,7 +201,7 @@ FOR_LOOP:
case _ = <-switchToConsensusTicker.C:
height, numPending, numUnassigned := bcR.pool.GetStatus()
outbound, inbound, _ := bcR.sw.NumPeers()
log.Debug("Consensus ticker", "numUnassigned", numUnassigned, "numPending", numPending,
log.Info("Consensus ticker", "numUnassigned", numUnassigned, "numPending", numPending,
"total", len(bcR.pool.requests), "outbound", outbound, "inbound", inbound)
// NOTE: this condition is very strict right now. may need to weaken
// If all `maxPendingRequests` requests are unassigned
@ -210,7 +210,7 @@ FOR_LOOP:
allUnassigned := numPending == numUnassigned
enoughPeers := outbound+inbound >= 3
if maxPending && allUnassigned && enoughPeers {
log.Info("Time to switch to consensus reactor!", "height", height)
log.Notice("Time to switch to consensus reactor!", "height", height)
bcR.pool.Stop()
conR := bcR.sw.Reactor("CONSENSUS").(consensusReactor)
@ -224,7 +224,7 @@ FOR_LOOP:
for i := 0; i < 10; i++ {
// See if there are any blocks to sync.
first, second := bcR.pool.PeekTwoBlocks()
//log.Debug("TrySync peeked", "first", first, "second", second)
//log.Info("TrySync peeked", "first", first, "second", second)
if first == nil || second == nil {
// We need both to sync the first block.
break SYNC_LOOP
@ -235,7 +235,7 @@ FOR_LOOP:
err := bcR.state.BondedValidators.VerifyValidation(
bcR.state.ChainID, first.Hash(), firstPartsHeader, first.Height, second.LastValidation)
if err != nil {
log.Debug("error in validation", "error", err)
log.Info("error in validation", "error", err)
bcR.pool.RedoRequest(first.Height)
break SYNC_LOOP
} else {

2
cmd/barak/main.go
View File

@ -86,7 +86,7 @@ func Run(authCommand AuthCommand) (interface{}, error) {
if err != nil {
return nil, err
}
log.Info(Fmt("Run() received command %v:%v", reflect.TypeOf(command), command))
log.Notice(Fmt("Run() received command %v:%v", reflect.TypeOf(command), command))
// Issue command
switch c := command.(type) {
case CommandStartProcess:

4
cmd/barak/validate.go
View File

@ -24,7 +24,7 @@ NOTE: Not used, just here in case we want it later.
func ValidateHandler(handler http.Handler, validators []Validator) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
sigStrs := r.Header[http.CanonicalHeaderKey("signatures")]
log.Debug("Woot", "sigstrs", sigStrs, "len", len(sigStrs))
log.Info("Woot", "sigstrs", sigStrs, "len", len(sigStrs))
// from https://medium.com/@xoen/golang-read-from-an-io-readwriter-without-loosing-its-content-2c6911805361
// Read the content
var bodyBytes []byte
@ -46,7 +46,7 @@ func ValidateHandler(handler http.Handler, validators []Validator) http.Handler
signBytes := binary.BinaryBytes(tuple)
// Validate the sign bytes.
//if validate(signBytes, validators,
log.Debug("Should sign", "bytes", signBytes)
log.Info("Should sign", "bytes", signBytes)
// If validation fails
// XXX
// If validation passes

4
cmd/tendermint/reset_priv_validator.go
View File

@ -18,11 +18,11 @@ func reset_priv_validator() {
privValidator.LastRound = 0
privValidator.LastStep = 0
privValidator.Save()
log.Info("Reset PrivValidator", "file", privValidatorFile)
log.Notice("Reset PrivValidator", "file", privValidatorFile)
} else {
privValidator = sm.GenPrivValidator()
privValidator.SetFile(privValidatorFile)
privValidator.Save()
log.Info("Generated PrivValidator", "file", privValidatorFile)
log.Notice("Generated PrivValidator", "file", privValidatorFile)
}
}

4
consensus/height_vote_set.go
View File

@ -78,7 +78,7 @@ func (hvs *HeightVoteSet) addRound(round int) {
if _, ok := hvs.roundVoteSets[round]; ok {
panic("addRound() for an existing round")
}
log.Debug("addRound(round)", "round", round)
log.Info("addRound(round)", "round", round)
prevotes := NewVoteSet(hvs.height, round, types.VoteTypePrevote, hvs.valSet)
precommits := NewVoteSet(hvs.height, round, types.VoteTypePrecommit, hvs.valSet)
hvs.roundVoteSets[round] = RoundVoteSet{
@ -135,7 +135,7 @@ func (hvs *HeightVoteSet) POLRound() int {
}
func (hvs *HeightVoteSet) getVoteSet(round int, type_ byte) *VoteSet {
log.Debug("getVoteSet(round)", "round", round, "type", type_)
log.Info("getVoteSet(round)", "round", round, "type", type_)
rvs, ok := hvs.roundVoteSets[round]
if !ok {
return nil

54
consensus/reactor.go
View File

@ -56,7 +56,7 @@ func NewConsensusReactor(consensusState *ConsensusState, blockStore *bc.BlockSto
// Implements Reactor
func (conR *ConsensusReactor) Start(sw *p2p.Switch) {
if atomic.CompareAndSwapUint32(&conR.running, 0, 1) {
log.Info("Starting ConsensusReactor", "fastSync", conR.fastSync)
log.Notice("Starting ConsensusReactor", "fastSync", conR.fastSync)
conR.sw = sw
if !conR.fastSync {
conR.conS.Start()
@ -68,7 +68,7 @@ func (conR *ConsensusReactor) Start(sw *p2p.Switch) {
// Implements Reactor
func (conR *ConsensusReactor) Stop() {
if atomic.CompareAndSwapUint32(&conR.running, 1, 0) {
log.Info("Stopping ConsensusReactor")
log.Notice("Stopping ConsensusReactor")
conR.conS.Stop()
close(conR.quit)
}
@ -133,8 +133,8 @@ func (conR *ConsensusReactor) RemovePeer(peer *p2p.Peer, reason interface{}) {
// Implements Reactor
// NOTE: We process these messages even when we're fast_syncing.
func (conR *ConsensusReactor) Receive(chId byte, peer *p2p.Peer, msgBytes []byte) {
log.Debug("Receive", "channel", chId, "peer", peer, "bytes", msgBytes)
if !conR.IsRunning() {
log.Debug("Receive", "channel", chId, "peer", peer, "bytes", msgBytes)
return
}
@ -146,7 +146,7 @@ func (conR *ConsensusReactor) Receive(chId byte, peer *p2p.Peer, msgBytes []byte
log.Warn("Error decoding message", "channel", chId, "peer", peer, "msg", msg, "error", err, "bytes", msgBytes)
return
}
log.Debug("Receive", "channel", chId, "peer", peer, "msg", msg, "rsHeight", rs.Height) //, "bytes", msgBytes)
log.Debug("Receive", "channel", chId, "peer", peer, "msg", msg, "rsHeight", rs.Height)
switch chId {
case StateChannel:
@ -275,7 +275,7 @@ func (conR *ConsensusReactor) SetPrivValidator(priv *sm.PrivValidator) {
// Switch from the fast_sync to the consensus:
// reset the state, turn off fast_sync, start the consensus-state-machine
func (conR *ConsensusReactor) SwitchToConsensus(state *sm.State) {
log.Info("SwitchToConsensus")
log.Notice("SwitchToConsensus")
// NOTE: The line below causes broadcastNewRoundStepRoutine() to
// broadcast a NewRoundStepMessage.
conR.conS.updateToState(state, false)
@ -349,7 +349,7 @@ OUTER_LOOP:
for {
// Manage disconnects from self or peer.
if !peer.IsRunning() || !conR.IsRunning() {
log.Info(Fmt("Stopping gossipDataRoutine for %v.", peer))
log.Notice(Fmt("Stopping gossipDataRoutine for %v.", peer))
return
}
rs := conR.conS.GetRoundState()
@ -357,7 +357,7 @@ OUTER_LOOP:
// Send proposal Block parts?
if rs.ProposalBlockParts.HasHeader(prs.ProposalBlockPartsHeader) {
//log.Debug("ProposalBlockParts matched", "blockParts", prs.ProposalBlockParts)
//log.Info("ProposalBlockParts matched", "blockParts", prs.ProposalBlockParts)
if index, ok := rs.ProposalBlockParts.BitArray().Sub(prs.ProposalBlockParts.Copy()).PickRandom(); ok {
part := rs.ProposalBlockParts.GetPart(index)
msg := &BlockPartMessage{
@ -373,12 +373,12 @@ OUTER_LOOP:
// If the peer is on a previous height, help catch up.
if (0 < prs.Height) && (prs.Height < rs.Height) {
//log.Debug("Data catchup", "height", rs.Height, "peerHeight", prs.Height, "peerProposalBlockParts", prs.ProposalBlockParts)
//log.Info("Data catchup", "height", rs.Height, "peerHeight", prs.Height, "peerProposalBlockParts", prs.ProposalBlockParts)
if index, ok := prs.ProposalBlockParts.Not().PickRandom(); ok {
// Ensure that the peer's PartSetHeader is correct
blockMeta := conR.blockStore.LoadBlockMeta(prs.Height)
if !blockMeta.PartsHeader.Equals(prs.ProposalBlockPartsHeader) {
log.Debug("Peer ProposalBlockPartsHeader mismatch, sleeping",
log.Info("Peer ProposalBlockPartsHeader mismatch, sleeping",
"peerHeight", prs.Height, "blockPartsHeader", blockMeta.PartsHeader, "peerBlockPartsHeader", prs.ProposalBlockPartsHeader)
time.Sleep(peerGossipSleepDuration)
continue OUTER_LOOP
@ -401,7 +401,7 @@ OUTER_LOOP:
ps.SetHasProposalBlockPart(prs.Height, prs.Round, index)
continue OUTER_LOOP
} else {
//log.Debug("No parts to send in catch-up, sleeping")
//log.Info("No parts to send in catch-up, sleeping")
time.Sleep(peerGossipSleepDuration)
continue OUTER_LOOP
}
@ -409,7 +409,7 @@ OUTER_LOOP:
// If height and round don't match, sleep.
if (rs.Height != prs.Height) || (rs.Round != prs.Round) {
//log.Debug("Peer Height|Round mismatch, sleeping", "peerHeight", prs.Height, "peerRound", prs.Round, "peer", peer)
//log.Info("Peer Height|Round mismatch, sleeping", "peerHeight", prs.Height, "peerRound", prs.Round, "peer", peer)
time.Sleep(peerGossipSleepDuration)
continue OUTER_LOOP
}
@ -458,7 +458,7 @@ OUTER_LOOP:
for {
// Manage disconnects from self or peer.
if !peer.IsRunning() || !conR.IsRunning() {
log.Info(Fmt("Stopping gossipVotesRoutine for %v.", peer))
log.Notice(Fmt("Stopping gossipVotesRoutine for %v.", peer))
return
}
rs := conR.conS.GetRoundState()
@ -479,35 +479,35 @@ OUTER_LOOP:
// If there are lastCommits to send...
if prs.Step == RoundStepNewHeight {
if ps.PickSendVote(rs.LastCommit) {
log.Debug("Picked rs.LastCommit to send")
log.Info("Picked rs.LastCommit to send")
continue OUTER_LOOP
}
}
// If there are prevotes to send...
if rs.Round == prs.Round && prs.Step <= RoundStepPrevote {
if ps.PickSendVote(rs.Votes.Prevotes(rs.Round)) {
log.Debug("Picked rs.Prevotes(rs.Round) to send")
log.Info("Picked rs.Prevotes(rs.Round) to send")
continue OUTER_LOOP
}
}
// If there are precommits to send...
if rs.Round == prs.Round && prs.Step <= RoundStepPrecommit {
if ps.PickSendVote(rs.Votes.Precommits(rs.Round)) {
log.Debug("Picked rs.Precommits(rs.Round) to send")
log.Info("Picked rs.Precommits(rs.Round) to send")
continue OUTER_LOOP
}
}
// If there are prevotes to send for the last round...
if rs.Round == prs.Round+1 && prs.Step <= RoundStepPrevote {
if ps.PickSendVote(rs.Votes.Prevotes(prs.Round)) {
log.Debug("Picked rs.Prevotes(prs.Round) to send")
log.Info("Picked rs.Prevotes(prs.Round) to send")
continue OUTER_LOOP
}
}
// If there are precommits to send for the last round...
if rs.Round == prs.Round+1 && prs.Step <= RoundStepPrecommit {
if ps.PickSendVote(rs.Votes.Precommits(prs.Round)) {
log.Debug("Picked rs.Precommits(prs.Round) to send")
log.Info("Picked rs.Precommits(prs.Round) to send")
continue OUTER_LOOP
}
}
@ -515,7 +515,7 @@ OUTER_LOOP:
if 0 <= prs.ProposalPOLRound {
if polPrevotes := rs.Votes.Prevotes(prs.ProposalPOLRound); polPrevotes != nil {
if ps.PickSendVote(polPrevotes) {
log.Debug("Picked rs.Prevotes(prs.ProposalPOLRound) to send")
log.Info("Picked rs.Prevotes(prs.ProposalPOLRound) to send")
continue OUTER_LOOP
}
}
@ -526,7 +526,7 @@ OUTER_LOOP:
// If peer is lagging by height 1, send LastCommit.
if prs.Height != 0 && rs.Height == prs.Height+1 {
if ps.PickSendVote(rs.LastCommit) {
log.Debug("Picked rs.LastCommit to send")
log.Info("Picked rs.LastCommit to send")
continue OUTER_LOOP
}
}
@ -537,9 +537,9 @@ OUTER_LOOP:
// Load the block validation for prs.Height,
// which contains precommit signatures for prs.Height.
validation := conR.blockStore.LoadBlockValidation(prs.Height)
log.Debug("Loaded BlockValidation for catch-up", "height", prs.Height, "validation", validation)
log.Info("Loaded BlockValidation for catch-up", "height", prs.Height, "validation", validation)
if ps.PickSendVote(validation) {
log.Debug("Picked Catchup validation to send")
log.Info("Picked Catchup validation to send")
continue OUTER_LOOP
}
}
@ -547,7 +547,7 @@ OUTER_LOOP:
if sleeping == 0 {
// We sent nothing. Sleep...
sleeping = 1
log.Debug("No votes to send, sleeping", "peer", peer,
log.Info("No votes to send, sleeping", "peer", peer,
"localPV", rs.Votes.Prevotes(rs.Round).BitArray(), "peerPV", prs.Prevotes,
"localPC", rs.Votes.Precommits(rs.Round).BitArray(), "peerPC", prs.Precommits)
} else if sleeping == 2 {
@ -783,23 +783,23 @@ func (ps *PeerState) setHasVote(height int, round int, type_ byte, index int) {
switch type_ {
case types.VoteTypePrevote:
ps.Prevotes.SetIndex(index, true)
log.Debug("SetHasVote(round-match)", "prevotes", ps.Prevotes, "index", index)
log.Info("SetHasVote(round-match)", "prevotes", ps.Prevotes, "index", index)
case types.VoteTypePrecommit:
ps.Precommits.SetIndex(index, true)
log.Debug("SetHasVote(round-match)", "precommits", ps.Precommits, "index", index)
log.Info("SetHasVote(round-match)", "precommits", ps.Precommits, "index", index)
}
} else if ps.CatchupCommitRound == round {
switch type_ {
case types.VoteTypePrevote:
case types.VoteTypePrecommit:
ps.CatchupCommit.SetIndex(index, true)
log.Debug("SetHasVote(CatchupCommit)", "precommits", ps.Precommits, "index", index)
log.Info("SetHasVote(CatchupCommit)", "precommits", ps.Precommits, "index", index)
}
} else if ps.ProposalPOLRound == round {
switch type_ {
case types.VoteTypePrevote:
ps.ProposalPOL.SetIndex(index, true)
log.Debug("SetHasVote(ProposalPOL)", "prevotes", ps.Prevotes, "index", index)
log.Info("SetHasVote(ProposalPOL)", "prevotes", ps.Prevotes, "index", index)
case types.VoteTypePrecommit:
}
}
@ -809,7 +809,7 @@ func (ps *PeerState) setHasVote(height int, round int, type_ byte, index int) {
case types.VoteTypePrevote:
case types.VoteTypePrecommit:
ps.LastCommit.SetIndex(index, true)
log.Debug("setHasVote(LastCommit)", "lastCommit", ps.LastCommit, "index", index)
log.Info("setHasVote(LastCommit)", "lastCommit", ps.LastCommit, "index", index)
}
}
} else {

80
consensus/state.go
View File

@ -365,14 +365,14 @@ func (cs *ConsensusState) NewStepCh() chan *RoundState {
func (cs *ConsensusState) Start() {
if atomic.CompareAndSwapUint32(&cs.started, 0, 1) {
log.Info("Starting ConsensusState")
log.Notice("Starting ConsensusState")
cs.scheduleRound0(cs.Height)
}
}
// EnterNewRound(height, 0) at cs.StartTime.
func (cs *ConsensusState) scheduleRound0(height int) {
//log.Debug("scheduleRound0", "now", time.Now(), "startTime", cs.StartTime)
//log.Info("scheduleRound0", "now", time.Now(), "startTime", cs.StartTime)
sleepDuration := cs.StartTime.Sub(time.Now())
go func() {
if 0 < sleepDuration {
@ -384,7 +384,7 @@ func (cs *ConsensusState) scheduleRound0(height int) {
func (cs *ConsensusState) Stop() {
if atomic.CompareAndSwapUint32(&cs.stopped, 0, 1) {
log.Info("Stopping ConsensusState")
log.Notice("Stopping ConsensusState")
close(cs.quit)
}
}
@ -409,7 +409,7 @@ func (cs *ConsensusState) updateToState(state *sm.State, contiguous bool) {
// This happens when SwitchToConsensus() is called in the reactor.
// We don't want to reset e.g. the Votes.
if cs.state != nil && (state.LastBlockHeight <= cs.state.LastBlockHeight) {
log.Info("Ignoring updateToState()", "newHeight", state.LastBlockHeight+1, "oldHeight", cs.state.LastBlockHeight+1)
log.Notice("Ignoring updateToState()", "newHeight", state.LastBlockHeight+1, "oldHeight", cs.state.LastBlockHeight+1)
return
}
@ -474,7 +474,7 @@ func (cs *ConsensusState) maybeRebond() {
log.Error("Failed to broadcast RebondTx",
"height", cs.Height, "round", cs.Round, "tx", rebondTx, "error", err)
} else {
log.Info("Signed and broadcast RebondTx",
log.Notice("Signed and broadcast RebondTx",
"height", cs.Height, "round", cs.Round, "tx", rebondTx)
}
} else {
@ -498,13 +498,13 @@ func (cs *ConsensusState) EnterNewRound(height int, round int) {
cs.mtx.Lock()
defer cs.mtx.Unlock()
if cs.Height != height || round < cs.Round || (cs.Round == round && cs.Step != RoundStepNewHeight) {
log.Debug(Fmt("EnterNewRound(%v/%v): Invalid args. Current step: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
log.Info(Fmt("EnterNewRound(%v/%v): Invalid args. Current step: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
return
}
if now := time.Now(); cs.StartTime.After(now) {
log.Warn("Need to set a buffer and log.Warn() here for sanity.", "startTime", cs.StartTime, "now", now)
}
log.Info(Fmt("EnterNewRound(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
log.Notice(Fmt("EnterNewRound(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
// Increment validators if necessary
validators := cs.Validators
@ -537,10 +537,10 @@ func (cs *ConsensusState) EnterPropose(height int, round int) {
cs.mtx.Lock()
defer cs.mtx.Unlock()
if cs.Height != height || round < cs.Round || (cs.Round == round && RoundStepPropose <= cs.Step) {
log.Debug(Fmt("EnterPropose(%v/%v): Invalid args. Current step: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
log.Info(Fmt("EnterPropose(%v/%v): Invalid args. Current step: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
return
}
log.Debug(Fmt("EnterPropose(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
log.Info(Fmt("EnterPropose(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
defer func() {
// Done EnterPropose:
@ -566,9 +566,9 @@ func (cs *ConsensusState) EnterPropose(height int, round int) {
}
if !bytes.Equal(cs.Validators.Proposer().Address, cs.privValidator.Address) {
log.Debug("EnterPropose: Not our turn to propose", "proposer", cs.Validators.Proposer().Address, "privValidator", cs.privValidator)
log.Info("EnterPropose: Not our turn to propose", "proposer", cs.Validators.Proposer().Address, "privValidator", cs.privValidator)
} else {
log.Debug("EnterPropose: Our turn to propose", "proposer", cs.Validators.Proposer().Address, "privValidator", cs.privValidator)
log.Info("EnterPropose: Our turn to propose", "proposer", cs.Validators.Proposer().Address, "privValidator", cs.privValidator)
cs.decideProposal(height, round)
}
}
@ -591,8 +591,8 @@ func (cs *ConsensusState) decideProposal(height int, round int) {
proposal := NewProposal(height, round, blockParts.Header(), cs.Votes.POLRound())
err := cs.privValidator.SignProposal(cs.state.ChainID, proposal)
if err == nil {
log.Info("Signed and set proposal", "height", height, "round", round, "proposal", proposal)
log.Debug(Fmt("Signed and set proposal block: %v", block))
log.Notice("Signed and set proposal", "height", height, "round", round, "proposal", proposal)
log.Info(Fmt("Signed and set proposal block: %v", block))
// Set fields
cs.Proposal = proposal
cs.ProposalBlock = block
@ -670,10 +670,10 @@ func (cs *ConsensusState) EnterPrevote(height int, round int) {
cs.mtx.Lock()
defer cs.mtx.Unlock()
if cs.Height != height || round < cs.Round || (cs.Round == round && RoundStepPrevote <= cs.Step) {
log.Debug(Fmt("EnterPrevote(%v/%v): Invalid args. Current step: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
log.Info(Fmt("EnterPrevote(%v/%v): Invalid args. Current step: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
return
}
log.Debug(Fmt("EnterPrevote(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
log.Info(Fmt("EnterPrevote(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
// Sign and broadcast vote as necessary
cs.doPrevote(height, round)
@ -691,7 +691,7 @@ func (cs *ConsensusState) EnterPrevote(height int, round int) {
func (cs *ConsensusState) doPrevote(height int, round int) {
// If a block is locked, prevote that.
if cs.LockedBlock != nil {
log.Debug("EnterPrevote: Block was locked")
log.Info("EnterPrevote: Block was locked")
cs.signAddVote(types.VoteTypePrevote, cs.LockedBlock.Hash(), cs.LockedBlockParts.Header())
return
}
@ -722,13 +722,13 @@ func (cs *ConsensusState) EnterPrevoteWait(height int, round int) {
cs.mtx.Lock()
defer cs.mtx.Unlock()
if cs.Height != height || round < cs.Round || (cs.Round == round && RoundStepPrevoteWait <= cs.Step) {
log.Debug(Fmt("EnterPrevoteWait(%v/%v): Invalid args. Current step: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
log.Info(Fmt("EnterPrevoteWait(%v/%v): Invalid args. Current step: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
return
}
if !cs.Votes.Prevotes(round).HasTwoThirdsAny() {
panic(Fmt("EnterPrevoteWait(%v/%v), but Prevotes does not have any +2/3 votes", height, round))
}
log.Debug(Fmt("EnterPrevoteWait(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
log.Info(Fmt("EnterPrevoteWait(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
// Done EnterPrevoteWait:
cs.Round = round
@ -752,10 +752,10 @@ func (cs *ConsensusState) EnterPrecommit(height int, round int) {
cs.mtx.Lock()
defer cs.mtx.Unlock()
if cs.Height != height || round < cs.Round || (cs.Round == round && RoundStepPrecommit <= cs.Step) {
log.Debug(Fmt("EnterPrecommit(%v/%v): Invalid args. Current step: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
log.Info(Fmt("EnterPrecommit(%v/%v): Invalid args. Current step: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
return
}
log.Debug(Fmt("EnterPrecommit(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
log.Info(Fmt("EnterPrecommit(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
defer func() {
// Done EnterPrecommit:
@ -773,10 +773,10 @@ func (cs *ConsensusState) EnterPrecommit(height int, round int) {
// If we don't have two thirds of prevotes, just precommit locked block or nil
if !ok {
if cs.LockedBlock != nil {
log.Debug("EnterPrecommit: No +2/3 prevotes during EnterPrecommit. Precommitting lock.")
log.Info("EnterPrecommit: No +2/3 prevotes during EnterPrecommit. Precommitting lock.")
cs.signAddVote(types.VoteTypePrecommit, cs.LockedBlock.Hash(), cs.LockedBlockParts.Header())
} else {
log.Debug("EnterPrecommit: No +2/3 prevotes during EnterPrecommit. Precommitting nil.")
log.Info("EnterPrecommit: No +2/3 prevotes during EnterPrecommit. Precommitting nil.")
cs.signAddVote(types.VoteTypePrecommit, nil, types.PartSetHeader{})
}
return
@ -785,9 +785,9 @@ func (cs *ConsensusState) EnterPrecommit(height int, round int) {
// +2/3 prevoted nil. Unlock and precommit nil.
if len(hash) == 0 {
if cs.LockedBlock == nil {
log.Debug("EnterPrecommit: +2/3 prevoted for nil.")
log.Info("EnterPrecommit: +2/3 prevoted for nil.")
} else {
log.Debug("EnterPrecommit: +2/3 prevoted for nil. Unlocking")
log.Info("EnterPrecommit: +2/3 prevoted for nil. Unlocking")
cs.LockedRound = 0
cs.LockedBlock = nil
cs.LockedBlockParts = nil
@ -800,14 +800,14 @@ func (cs *ConsensusState) EnterPrecommit(height int, round int) {
// If +2/3 prevoted for already locked block, precommit it.
if cs.LockedBlock.HashesTo(hash) {
log.Debug("EnterPrecommit: +2/3 prevoted locked block.")
log.Info("EnterPrecommit: +2/3 prevoted locked block.")
cs.signAddVote(types.VoteTypePrecommit, hash, partsHeader)
return
}
// If +2/3 prevoted for proposal block, stage and precommit it
if cs.ProposalBlock.HashesTo(hash) {
log.Debug("EnterPrecommit: +2/3 prevoted proposal block.")
log.Info("EnterPrecommit: +2/3 prevoted proposal block.")
// Validate the block.
if err := cs.stageBlock(cs.ProposalBlock, cs.ProposalBlockParts); err != nil {
panic(Fmt("EnterPrecommit: +2/3 prevoted for an invalid block: %v", err))
@ -841,13 +841,13 @@ func (cs *ConsensusState) EnterPrecommitWait(height int, round int) {
cs.mtx.Lock()
defer cs.mtx.Unlock()
if cs.Height != height || round < cs.Round || (cs.Round == round && RoundStepPrecommitWait <= cs.Step) {
log.Debug(Fmt("EnterPrecommitWait(%v/%v): Invalid args. Current step: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
log.Info(Fmt("EnterPrecommitWait(%v/%v): Invalid args. Current step: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
return
}
if !cs.Votes.Precommits(round).HasTwoThirdsAny() {
panic(Fmt("EnterPrecommitWait(%v/%v), but Precommits does not have any +2/3 votes", height, round))
}
log.Debug(Fmt("EnterPrecommitWait(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
log.Info(Fmt("EnterPrecommitWait(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
// Done EnterPrecommitWait:
cs.Round = round
@ -870,10 +870,10 @@ func (cs *ConsensusState) EnterCommit(height int) {
cs.mtx.Lock()
defer cs.mtx.Unlock()
if cs.Height != height || RoundStepCommit <= cs.Step {
log.Debug(Fmt("EnterCommit(%v): Invalid args. Current step: %v/%v/%v", height, cs.Height, cs.Round, cs.Step))
log.Info(Fmt("EnterCommit(%v): Invalid args. Current step: %v/%v/%v", height, cs.Height, cs.Round, cs.Step))
return
}
log.Debug(Fmt("EnterCommit(%v). Current: %v/%v/%v", height, cs.Height, cs.Round, cs.Step))
log.Info(Fmt("EnterCommit(%v). Current: %v/%v/%v", height, cs.Height, cs.Round, cs.Step))
defer func() {
// Done Entercommit:
@ -944,7 +944,7 @@ func (cs *ConsensusState) FinalizeCommit(height int) {
defer cs.mtx.Unlock()
if cs.Height != height || cs.Step != RoundStepCommit {
log.Debug(Fmt("FinalizeCommit(%v): Invalid args. Current step: %v/%v/%v", height, cs.Height, cs.Round, cs.Step))
log.Info(Fmt("FinalizeCommit(%v): Invalid args. Current step: %v/%v/%v", height, cs.Height, cs.Round, cs.Step))
return
}
@ -965,7 +965,7 @@ func (cs *ConsensusState) FinalizeCommit(height int) {
}
// END SANITY CHECK
log.Debug(Fmt("Finalizing commit of block: %v", cs.ProposalBlock))
log.Info(Fmt("Finalizing commit of block: %v", cs.ProposalBlock))
// We have the block, so stage/save/commit-vote.
cs.saveBlock(cs.ProposalBlock, cs.ProposalBlockParts, cs.Votes.Precommits(cs.Round))
// Increment height.
@ -1044,7 +1044,7 @@ func (cs *ConsensusState) AddProposalBlockPart(height int, part *types.Part) (ad
var n int64
var err error
cs.ProposalBlock = binary.ReadBinary(&types.Block{}, cs.ProposalBlockParts.GetReader(), &n, &err).(*types.Block)
log.Debug("Received complete proposal", "hash", cs.ProposalBlock.Hash())
log.Info("Received complete proposal", "hash", cs.ProposalBlock.Hash())
if cs.Step == RoundStepPropose && cs.isProposalComplete() {
// Move onto the next step
go cs.EnterPrevote(height, cs.Round)
@ -1067,13 +1067,13 @@ func (cs *ConsensusState) AddVote(address []byte, vote *types.Vote, peerKey stri
//-----------------------------------------------------------------------------
func (cs *ConsensusState) addVote(address []byte, vote *types.Vote, peerKey string) (added bool, index int, err error) {
log.Debug("addVote", "voteHeight", vote.Height, "voteType", vote.Type, "csHeight", cs.Height)
log.Info("addVote", "voteHeight", vote.Height, "voteType", vote.Type, "csHeight", cs.Height)
// A precommit for the previous height?
if vote.Height+1 == cs.Height && vote.Type == types.VoteTypePrecommit {
added, index, err = cs.LastCommit.AddByAddress(address, vote)
if added {
log.Debug(Fmt("Added to lastPrecommits: %v", cs.LastCommit.StringShort()))
log.Info(Fmt("Added to lastPrecommits: %v", cs.LastCommit.StringShort()))
}
return
}
@ -1086,7 +1086,7 @@ func (cs *ConsensusState) addVote(address []byte, vote *types.Vote, peerKey stri
switch vote.Type {
case types.VoteTypePrevote:
prevotes := cs.Votes.Prevotes(vote.Round)
log.Debug(Fmt("Added to prevotes: %v", prevotes.StringShort()))
log.Info(Fmt("Added to prevotes: %v", prevotes.StringShort()))
// First, unlock if prevotes is a valid POL.
// >> lockRound < POLRound <= unlockOrChangeLockRound (see spec)
// NOTE: If (lockRound < POLRound) but !(POLRound <= unlockOrChangeLockRound),
@ -1095,7 +1095,7 @@ func (cs *ConsensusState) addVote(address []byte, vote *types.Vote, peerKey stri
if (cs.LockedBlock != nil) && (cs.LockedRound < vote.Round) && (vote.Round <= cs.Round) {
hash, _, ok := prevotes.TwoThirdsMajority()
if ok && !cs.LockedBlock.HashesTo(hash) {
log.Info("Unlocking because of POL.", "lockedRound", cs.LockedRound, "POLRound", vote.Round)
log.Notice("Unlocking because of POL.", "lockedRound", cs.LockedRound, "POLRound", vote.Round)
cs.LockedRound = 0
cs.LockedBlock = nil
cs.LockedBlockParts = nil
@ -1122,7 +1122,7 @@ func (cs *ConsensusState) addVote(address []byte, vote *types.Vote, peerKey stri
}
case types.VoteTypePrecommit:
precommits := cs.Votes.Precommits(vote.Round)
log.Debug(Fmt("Added to precommit: %v", precommits.StringShort()))
log.Info(Fmt("Added to precommit: %v", precommits.StringShort()))
if cs.Round <= vote.Round && precommits.HasTwoThirdsAny() {
go func() {
hash, _, ok := precommits.TwoThirdsMajority()
@ -1149,7 +1149,7 @@ func (cs *ConsensusState) addVote(address []byte, vote *types.Vote, peerKey stri
}
// Height mismatch, bad peer?
log.Debug("Vote ignored and not added", "voteHeight", vote.Height, "csHeight", cs.Height)
log.Info("Vote ignored and not added", "voteHeight", vote.Height, "csHeight", cs.Height)
return
}
@ -1196,7 +1196,7 @@ func (cs *ConsensusState) signAddVote(type_ byte, hash []byte, header types.Part
err := cs.privValidator.SignVote(cs.state.ChainID, vote)
if err == nil {
_, _, err := cs.addVote(cs.privValidator.Address, vote, "")
log.Info("Signed and added vote", "height", cs.Height, "round", cs.Round, "vote", vote, "error", err)
log.Notice("Signed and added vote", "height", cs.Height, "round", cs.Round, "vote", vote, "error", err)
return vote
} else {
log.Warn("Error signing vote", "height", cs.Height, "round", cs.Round, "vote", vote, "error", err)

16
mempool/mempool.go
View File

@ -43,10 +43,10 @@ func (mem *Mempool) AddTx(tx types.Tx) (err error) {
defer mem.mtx.Unlock()
err = sm.ExecTx(mem.cache, tx, false, nil)
if err != nil {
log.Debug("AddTx() error", "tx", tx, "error", err)
log.Info("AddTx() error", "tx", tx, "error", err)
return err
} else {
log.Debug("AddTx() success", "tx", tx)
log.Info("AddTx() success", "tx", tx)
mem.txs = append(mem.txs, tx)
return nil
}
@ -55,7 +55,7 @@ func (mem *Mempool) AddTx(tx types.Tx) (err error) {
func (mem *Mempool) GetProposalTxs() []types.Tx {
mem.mtx.Lock()
defer mem.mtx.Unlock()
log.Debug("GetProposalTxs:", "txs", mem.txs)
log.Info("GetProposalTxs:", "txs", mem.txs)
return mem.txs
}
@ -80,10 +80,10 @@ func (mem *Mempool) ResetForBlockAndState(block *types.Block, state *sm.State) {
for _, tx := range mem.txs {
txID := types.TxID(state.ChainID, tx)
if _, ok := blockTxsMap[string(txID)]; ok {
log.Debug("Filter out, already committed", "tx", tx, "txID", txID)
log.Info("Filter out, already committed", "tx", tx, "txID", txID)
continue
} else {
log.Debug("Filter in, still new", "tx", tx, "txID", txID)
log.Info("Filter in, still new", "tx", tx, "txID", txID)
txs = append(txs, tx)
}
}
@ -93,15 +93,15 @@ func (mem *Mempool) ResetForBlockAndState(block *types.Block, state *sm.State) {
for _, tx := range txs {
err := sm.ExecTx(mem.cache, tx, false, nil)
if err == nil {
log.Debug("Filter in, valid", "tx", tx)
log.Info("Filter in, valid", "tx", tx)
validTxs = append(validTxs, tx)
} else {
// tx is no longer valid.
log.Debug("Filter out, no longer valid", "tx", tx, "error", err)
log.Info("Filter out, no longer valid", "tx", tx, "error", err)
}
}
// We're done!
log.Debug("New txs", "txs", validTxs, "oldTxs", mem.txs)
log.Info("New txs", "txs", validTxs, "oldTxs", mem.txs)
mem.txs = validTxs
}

10
mempool/reactor.go
View File

@ -41,14 +41,14 @@ func NewMempoolReactor(mempool *Mempool) *MempoolReactor {
func (memR *MempoolReactor) Start(sw *p2p.Switch) {
if atomic.CompareAndSwapUint32(&memR.started, 0, 1) {
memR.sw = sw
log.Info("Starting MempoolReactor")
log.Notice("Starting MempoolReactor")
}
}
// Implements Reactor
func (memR *MempoolReactor) Stop() {
if atomic.CompareAndSwapUint32(&memR.stopped, 0, 1) {
log.Info("Stopping MempoolReactor")
log.Notice("Stopping MempoolReactor")
close(memR.quit)
}
}
@ -78,17 +78,17 @@ func (memR *MempoolReactor) Receive(chId byte, src *p2p.Peer, msgBytes []byte) {
log.Warn("Error decoding message", "error", err)
return
}
log.Info("MempoolReactor received message", "msg", msg)
log.Notice("MempoolReactor received message", "msg", msg)
switch msg := msg.(type) {
case *TxMessage:
err := memR.Mempool.AddTx(msg.Tx)
if err != nil {
// Bad, seen, or conflicting tx.
log.Debug("Could not add tx", "tx", msg.Tx)
log.Info("Could not add tx", "tx", msg.Tx)
return
} else {
log.Debug("Added valid tx", "tx", msg.Tx)
log.Info("Added valid tx", "tx", msg.Tx)
}
// Share tx.
// We use a simple shotgun approach for now.

13
node/node.go
View File

@ -84,13 +84,13 @@ func NewNode() *Node {
privValidatorFile := config.GetString("priv_validator_file")
if _, err := os.Stat(privValidatorFile); err == nil {
privValidator = sm.LoadPrivValidator(privValidatorFile)
log.Info("Loaded PrivValidator",
log.Notice("Loaded PrivValidator",
"file", privValidatorFile, "privValidator", privValidator)
} else {
privValidator = sm.GenPrivValidator()
privValidator.SetFile(privValidatorFile)
privValidator.Save()
log.Info("Generated PrivValidator", "file", privValidatorFile)
log.Notice("Generated PrivValidator", "file", privValidatorFile)
}
// Generate node PrivKey
@ -147,7 +147,6 @@ func NewNode() *Node {
// Call Start() after adding the listeners.
func (n *Node) Start() {
log.Info("Starting Node", "chainID", config.GetString("chain_id"))
n.book.Start()
n.sw.SetNodeInfo(makeNodeInfo(n.sw, n.privKey))
n.sw.SetNodePrivKey(n.privKey)
@ -155,7 +154,7 @@ func (n *Node) Start() {
}
func (n *Node) Stop() {
log.Info("Stopping Node")
log.Notice("Stopping Node")
// TODO: gracefully disconnect from peers.
n.sw.Stop()
n.book.Stop()
@ -172,7 +171,7 @@ func SetFireable(evsw *events.EventSwitch, eventables ...events.Eventable) {
// Add listeners before starting the Node.
// The first listener is the primary listener (in NodeInfo)
func (n *Node) AddListener(l p2p.Listener) {
log.Info(Fmt("Added %v", l))
log.Notice(Fmt("Added %v", l))
n.sw.AddListener(l)
n.book.AddOurAddress(l.ExternalAddress())
}
@ -200,7 +199,7 @@ func (n *Node) dialSeed(addr *p2p.NetAddress) {
//n.book.MarkAttempt(addr)
return
} else {
log.Info("Connected to seed", "peer", peer)
log.Notice("Connected to seed", "peer", peer)
n.book.AddAddress(addr, addr)
}
}
@ -291,6 +290,8 @@ func RunNode() {
n.AddListener(l)
n.Start()
log.Notice("Started node", "nodeInfo", n.sw.NodeInfo())
// If seedNode is provided by config, dial out.
if config.GetString("seeds") != "" {
n.DialSeed()

18
p2p/addrbook.go
View File

@ -126,7 +126,7 @@ func (a *AddrBook) init() {
func (a *AddrBook) Start() {
if atomic.CompareAndSwapUint32(&a.started, 0, 1) {
log.Info("Starting AddrBook")
log.Notice("Starting AddrBook")
a.loadFromFile(a.filePath)
a.wg.Add(1)
go a.saveRoutine()
@ -135,7 +135,7 @@ func (a *AddrBook) Start() {
func (a *AddrBook) Stop() {
if atomic.CompareAndSwapUint32(&a.stopped, 0, 1) {
log.Info("Stopping AddrBook")
log.Notice("Stopping AddrBook")
close(a.quit)
a.wg.Wait()
}
@ -144,7 +144,7 @@ func (a *AddrBook) Stop() {
func (a *AddrBook) AddOurAddress(addr *NetAddress) {
a.mtx.Lock()
defer a.mtx.Unlock()
log.Debug("Add our address to book", "addr", addr)
log.Info("Add our address to book", "addr", addr)
a.ourAddrs[addr.String()] = addr
}
@ -159,7 +159,7 @@ func (a *AddrBook) OurAddresses() []*NetAddress {
func (a *AddrBook) AddAddress(addr *NetAddress, src *NetAddress) {
a.mtx.Lock()
defer a.mtx.Unlock()
log.Debug("Add address to book", "addr", addr, "src", src)
log.Info("Add address to book", "addr", addr, "src", src)
a.addAddress(addr, src)
}
@ -379,7 +379,7 @@ out:
for {
select {
case <-dumpAddressTicker.C:
log.Debug("Saving AddrBook to file", "size", a.Size())
log.Info("Saving AddrBook to file", "size", a.Size())
a.saveToFile(a.filePath)
case <-a.quit:
break out
@ -388,7 +388,7 @@ out:
dumpAddressTicker.Stop()
a.saveToFile(a.filePath)
a.wg.Done()
log.Info("Address handler done")
log.Notice("Address handler done")
}
func (a *AddrBook) getBucket(bucketType byte, bucketIdx int) map[string]*knownAddress {
@ -421,7 +421,7 @@ func (a *AddrBook) addToNewBucket(ka *knownAddress, bucketIdx int) bool {
// Enforce max addresses.
if len(bucket) > newBucketSize {
log.Info("new bucket is full, expiring old ")
log.Notice("new bucket is full, expiring old ")
a.expireNew(bucketIdx)
}
@ -549,7 +549,7 @@ func (a *AddrBook) addAddress(addr, src *NetAddress) {
bucket := a.calcNewBucket(addr, src)
a.addToNewBucket(ka, bucket)
log.Info("Added new address", "address", addr, "total", a.size())
log.Notice("Added new address", "address", addr, "total", a.size())
}
// Make space in the new buckets by expiring the really bad entries.
@ -558,7 +558,7 @@ func (a *AddrBook) expireNew(bucketIdx int) {
for addrStr, ka := range a.addrNew[bucketIdx] {
// If an entry is bad, throw it away
if ka.isBad() {
log.Info(Fmt("expiring bad address %v", addrStr))
log.Notice(Fmt("expiring bad address %v", addrStr))
a.removeFromBucket(ka, bucketTypeNew, bucketIdx)
return
}

20
p2p/connection.go
View File

@ -124,7 +124,7 @@ func NewMConnection(conn net.Conn, chDescs []*ChannelDescriptor, onReceive recei
// .Start() begins multiplexing packets to and from "channels".
func (c *MConnection) Start() {
if atomic.CompareAndSwapUint32(&c.started, 0, 1) {
log.Debug("Starting MConnection", "connection", c)
log.Info("Starting MConnection", "connection", c)
go c.sendRoutine()
go c.recvRoutine()
}
@ -132,7 +132,7 @@ func (c *MConnection) Start() {
func (c *MConnection) Stop() {
if atomic.CompareAndSwapUint32(&c.stopped, 0, 1) {
log.Debug("Stopping MConnection", "connection", c)
log.Info("Stopping MConnection", "connection", c)
close(c.quit)
c.conn.Close()
c.flushTimer.Stop()
@ -182,7 +182,7 @@ func (c *MConnection) Send(chId byte, msg interface{}) bool {
return false
}
log.Debug("Send", "channel", chId, "connection", c, "msg", msg) //, "bytes", binary.BinaryBytes(msg))
log.Info("Send", "channel", chId, "connection", c, "msg", msg) //, "bytes", binary.BinaryBytes(msg))
// Send message to channel.
channel, ok := c.channelsIdx[chId]
@ -211,7 +211,7 @@ func (c *MConnection) TrySend(chId byte, msg interface{}) bool {
return false
}
log.Debug("TrySend", "channel", chId, "connection", c, "msg", msg)
log.Info("TrySend", "channel", chId, "connection", c, "msg", msg)
// Send message to channel.
channel, ok := c.channelsIdx[chId]
@ -263,12 +263,12 @@ FOR_LOOP:
channel.updateStats()
}
case <-c.pingTimer.Ch:
log.Debug("Send Ping")
log.Info("Send Ping")
binary.WriteByte(packetTypePing, c.bufWriter, &n, &err)
c.sendMonitor.Update(int(n))
c.flush()
case <-c.pong:
log.Debug("Send Pong")
log.Info("Send Pong")
binary.WriteByte(packetTypePong, c.bufWriter, &n, &err)
c.sendMonitor.Update(int(n))
c.flush()
@ -339,7 +339,7 @@ func (c *MConnection) sendMsgPacket() bool {
if leastChannel == nil {
return true
} else {
// log.Debug("Found a msgPacket to send")
// log.Info("Found a msgPacket to send")
}
// Make & send a msgPacket from this channel
@ -368,7 +368,7 @@ FOR_LOOP:
/*
// Peek into bufReader for debugging
if numBytes := c.bufReader.Buffered(); numBytes > 0 {
log.Debug("Peek connection buffer", "numBytes", numBytes, "bytes", log15.Lazy{func() []byte {
log.Info("Peek connection buffer", "numBytes", numBytes, "bytes", log15.Lazy{func() []byte {
bytes, err := c.bufReader.Peek(MinInt(numBytes, 100))
if err == nil {
return bytes
@ -397,11 +397,11 @@ FOR_LOOP:
switch pktType {
case packetTypePing:
// TODO: prevent abuse, as they cause flush()'s.
log.Debug("Receive Ping")
log.Info("Receive Ping")
c.pong <- struct{}{}
case packetTypePong:
// do nothing
log.Debug("Receive Pong")
log.Info("Receive Pong")
case packetTypeMsg:
pkt, n, err := msgPacket{}, int64(0), error(nil)
binary.ReadBinaryPtr(&pkt, c.bufReader, &n, &err)

12
p2p/listener.go
View File

@ -55,7 +55,7 @@ func NewDefaultListener(protocol string, lAddr string, requireUPNPHairpin bool)
}
// Actual listener local IP & port
listenerIP, listenerPort := splitHostPort(listener.Addr().String())
log.Debug("Local listener", "ip", listenerIP, "port", listenerPort)
log.Info("Local listener", "ip", listenerIP, "port", listenerPort)
// Determine internal address...
var intAddr *NetAddress = NewNetAddressString(lAddr)
@ -157,16 +157,16 @@ func (l *DefaultListener) String() string {
// UPNP external address discovery & port mapping
func getUPNPExternalAddress(externalPort, internalPort int) *NetAddress {
log.Debug("Getting UPNP external address")
log.Info("Getting UPNP external address")
nat, err := upnp.Discover()
if err != nil {
log.Debug("Could not perform UPNP discover", "error", err)
log.Info("Could not perform UPNP discover", "error", err)
return nil
}
ext, err := nat.GetExternalAddress()
if err != nil {
log.Debug("Could not get UPNP external address", "error", err)
log.Info("Could not get UPNP external address", "error", err)
return nil
}
@ -177,11 +177,11 @@ func getUPNPExternalAddress(externalPort, internalPort int) *NetAddress {
externalPort, err = nat.AddPortMapping("tcp", externalPort, internalPort, "tendermint", 0)
if err != nil {
log.Debug("Could not add UPNP port mapping", "error", err)
log.Info("Could not add UPNP port mapping", "error", err)
return nil
}
log.Debug("Got UPNP external address", "address", ext)
log.Info("Got UPNP external address", "address", ext)
return NewNetAddressIPPort(ext, uint16(externalPort))
}

6
p2p/peer.go
View File

@ -35,7 +35,7 @@ func peerHandshake(conn net.Conn, ourNodeInfo *types.NodeInfo) (*types.NodeInfo,
func() {
var n int64
binary.ReadBinary(peerNodeInfo, conn, &n, &err2)
log.Info("Peer handshake", "peerNodeInfo", peerNodeInfo)
log.Notice("Peer handshake", "peerNodeInfo", peerNodeInfo)
})
if err1 != nil {
return nil, err1
@ -74,14 +74,14 @@ func newPeer(conn net.Conn, peerNodeInfo *types.NodeInfo, outbound bool, reactor
func (p *Peer) start() {
if atomic.CompareAndSwapUint32(&p.running, 0, 1) {
log.Debug("Starting Peer", "peer", p)
log.Info("Starting Peer", "peer", p)
p.mconn.Start()
}
}
func (p *Peer) stop() {
if atomic.CompareAndSwapUint32(&p.running, 1, 0) {
log.Debug("Stopping Peer", "peer", p)
log.Info("Stopping Peer", "peer", p)
p.mconn.Stop()
}
}

14
p2p/pex_reactor.go
View File

@ -48,7 +48,7 @@ func NewPEXReactor(book *AddrBook) *PEXReactor {
// Implements Reactor
func (pexR *PEXReactor) Start(sw *Switch) {
if atomic.CompareAndSwapUint32(&pexR.started, 0, 1) {
log.Info("Starting PEXReactor")
log.Notice("Starting PEXReactor")
pexR.sw = sw
go pexR.ensurePeersRoutine()
}
@ -57,7 +57,7 @@ func (pexR *PEXReactor) Start(sw *Switch) {
// Implements Reactor
func (pexR *PEXReactor) Stop() {
if atomic.CompareAndSwapUint32(&pexR.stopped, 0, 1) {
log.Info("Stopping PEXReactor")
log.Notice("Stopping PEXReactor")
close(pexR.quit)
}
}
@ -103,7 +103,7 @@ func (pexR *PEXReactor) Receive(chId byte, src *Peer, msgBytes []byte) {
log.Warn("Error decoding message", "error", err)
return
}
log.Info("Received message", "msg", msg)
log.Notice("Received message", "msg", msg)
switch msg := msg.(type) {
case *pexRequestMessage:
@ -160,7 +160,7 @@ FOR_LOOP:
func (pexR *PEXReactor) ensurePeers() {
numOutPeers, _, numDialing := pexR.sw.NumPeers()
numToDial := minNumOutboundPeers - (numOutPeers + numDialing)
log.Debug("Ensure peers", "numOutPeers", numOutPeers, "numDialing", numDialing, "numToDial", numToDial)
log.Info("Ensure peers", "numOutPeers", numOutPeers, "numDialing", numDialing, "numToDial", numToDial)
if numToDial <= 0 {
return
}
@ -183,14 +183,14 @@ func (pexR *PEXReactor) ensurePeers() {
alreadyConnected := pexR.sw.Peers().Has(try.IP.String())
if alreadySelected || alreadyDialing || alreadyConnected {
/*
log.Debug("Cannot dial address", "addr", try,
log.Info("Cannot dial address", "addr", try,
"alreadySelected", alreadySelected,
"alreadyDialing", alreadyDialing,
"alreadyConnected", alreadyConnected)
*/
continue
} else {
log.Debug("Will dial address", "addr", try)
log.Info("Will dial address", "addr", try)
picked = try
break
}
@ -216,7 +216,7 @@ func (pexR *PEXReactor) ensurePeers() {
if peers := pexR.sw.Peers().List(); len(peers) > 0 {
i := rand.Int() % len(peers)
peer := peers[i]
log.Debug("No addresses to dial. Sending pexRequest to random peer", "peer", peer)
log.Info("No addresses to dial. Sending pexRequest to random peer", "peer", peer)
pexR.RequestPEX(peer)
}
}

24
p2p/switch.go
View File

@ -223,7 +223,7 @@ func (sw *Switch) AddPeerWithConnection(conn net.Conn, outbound bool) (*Peer, er
// Add the peer to .peers
// ignore if duplicate or if we already have too many for that IP range
if err := sw.peers.Add(peer); err != nil {
log.Info("Ignoring peer", "error", err, "peer", peer)
log.Notice("Ignoring peer", "error", err, "peer", peer)
peer.mconn.Stop()
return nil, err
}
@ -234,7 +234,7 @@ func (sw *Switch) AddPeerWithConnection(conn net.Conn, outbound bool) (*Peer, er
sw.startInitPeer(peer)
}
log.Info("Added peer", "peer", peer)
log.Notice("Added peer", "peer", peer)
return peer, nil
}
@ -244,20 +244,20 @@ func (sw *Switch) startInitPeer(peer *Peer) {
}
func (sw *Switch) DialPeerWithAddress(addr *NetAddress) (*Peer, error) {
log.Debug("Dialing address", "address", addr)
log.Info("Dialing address", "address", addr)
sw.dialing.Set(addr.IP.String(), addr)
conn, err := addr.DialTimeout(peerDialTimeoutSeconds * time.Second)
sw.dialing.Delete(addr.IP.String())
if err != nil {
log.Debug("Failed dialing address", "address", addr, "error", err)
log.Info("Failed dialing address", "address", addr, "error", err)
return nil, err
}
peer, err := sw.AddPeerWithConnection(conn, true)
if err != nil {
log.Debug("Failed adding peer", "address", addr, "conn", conn, "error", err)
log.Info("Failed adding peer", "address", addr, "conn", conn, "error", err)
return nil, err
}
log.Info("Dialed and added peer", "address", addr, "peer", peer)
log.Notice("Dialed and added peer", "address", addr, "peer", peer)
return peer, nil
}
@ -270,7 +270,7 @@ func (sw *Switch) IsDialing(addr *NetAddress) bool {
// which receives success values for each attempted send (false if times out)
func (sw *Switch) Broadcast(chId byte, msg interface{}) chan bool {
successChan := make(chan bool, len(sw.peers.List()))
log.Debug("Broadcast", "channel", chId, "msg", msg)
log.Info("Broadcast", "channel", chId, "msg", msg)
for _, peer := range sw.peers.List() {
go func(peer *Peer) {
success := peer.Send(chId, msg)
@ -302,7 +302,7 @@ func (sw *Switch) Peers() IPeerSet {
// Disconnect from a peer due to external error.
// TODO: make record depending on reason.
func (sw *Switch) StopPeerForError(peer *Peer, reason interface{}) {
log.Info("Stopping peer for error", "peer", peer, "error", reason)
log.Notice("Stopping peer for error", "peer", peer, "error", reason)
sw.peers.Remove(peer)
peer.stop()
sw.removePeerFromReactors(peer, reason)
@ -311,7 +311,7 @@ func (sw *Switch) StopPeerForError(peer *Peer, reason interface{}) {
// Disconnect from a peer gracefully.
// TODO: handle graceful disconnects.
func (sw *Switch) StopPeerGracefully(peer *Peer) {
log.Info("Stopping peer gracefully")
log.Notice("Stopping peer gracefully")
sw.peers.Remove(peer)
peer.stop()
sw.removePeerFromReactors(peer, nil)
@ -338,20 +338,20 @@ func (sw *Switch) listenerRoutine(l Listener) {
// ignore connection if we already have enough
if maxNumPeers <= sw.peers.Size() {
log.Debug("Ignoring inbound connection: already have enough peers", "conn", inConn, "numPeers", sw.peers.Size(), "max", maxNumPeers)
log.Info("Ignoring inbound connection: already have enough peers", "address", inConn.RemoteAddr().String(), "numPeers", sw.peers.Size(), "max", maxNumPeers)
continue
}
// Ignore connections from IP ranges for which we have too many
if sw.peers.HasMaxForIPRange(inConn) {
log.Debug("Ignoring inbound connection: already have enough peers for that IP range", "address", inConn.RemoteAddr().String())
log.Info("Ignoring inbound connection: already have enough peers for that IP range", "address", inConn.RemoteAddr().String())
continue
}
// New inbound connection!
_, err := sw.AddPeerWithConnection(inConn, false)
if err != nil {
log.Info("Ignoring inbound connection: error on AddPeerWithConnection", "conn", inConn, "error", err)
log.Notice("Ignoring inbound connection: error on AddPeerWithConnection", "address", inConn.RemoteAddr().String(), "error", err)
continue
}

22
p2p/upnp/probe.go
View File

@ -19,19 +19,19 @@ func makeUPNPListener(intPort int, extPort int) (NAT, net.Listener, net.IP, erro
if err != nil {
return nil, nil, nil, errors.New(fmt.Sprintf("NAT upnp could not be discovered: %v", err))
}
log.Debug(Fmt("ourIP: %v", nat.(*upnpNAT).ourIP))
log.Info(Fmt("ourIP: %v", nat.(*upnpNAT).ourIP))
ext, err := nat.GetExternalAddress()
if err != nil {
return nat, nil, nil, errors.New(fmt.Sprintf("External address error: %v", err))
}
log.Debug(Fmt("External address: %v", ext))
log.Info(Fmt("External address: %v", ext))
port, err := nat.AddPortMapping("tcp", extPort, intPort, "Tendermint UPnP Probe", 0)
if err != nil {
return nat, nil, ext, errors.New(fmt.Sprintf("Port mapping error: %v", err))
}
log.Debug(Fmt("Port mapping mapped: %v", port))
log.Info(Fmt("Port mapping mapped: %v", port))
// also run the listener, open for all remote addresses.
listener, err := net.Listen("tcp", fmt.Sprintf(":%v", intPort))
@ -46,17 +46,17 @@ func testHairpin(listener net.Listener, extAddr string) (supportsHairpin bool) {
go func() {
inConn, err := listener.Accept()
if err != nil {
log.Info(Fmt("Listener.Accept() error: %v", err))
log.Notice(Fmt("Listener.Accept() error: %v", err))
return
}
log.Debug(Fmt("Accepted incoming connection: %v -> %v", inConn.LocalAddr(), inConn.RemoteAddr()))
log.Info(Fmt("Accepted incoming connection: %v -> %v", inConn.LocalAddr(), inConn.RemoteAddr()))
buf := make([]byte, 1024)
n, err := inConn.Read(buf)
if err != nil {
log.Info(Fmt("Incoming connection read error: %v", err))
log.Notice(Fmt("Incoming connection read error: %v", err))
return
}
log.Debug(Fmt("Incoming connection read %v bytes: %X", n, buf))
log.Info(Fmt("Incoming connection read %v bytes: %X", n, buf))
if string(buf) == "test data" {
supportsHairpin = true
return
@ -66,16 +66,16 @@ func testHairpin(listener net.Listener, extAddr string) (supportsHairpin bool) {
// Establish outgoing
outConn, err := net.Dial("tcp", extAddr)
if err != nil {
log.Info(Fmt("Outgoing connection dial error: %v", err))
log.Notice(Fmt("Outgoing connection dial error: %v", err))
return
}
n, err := outConn.Write([]byte("test data"))
if err != nil {
log.Info(Fmt("Outgoing connection write error: %v", err))
log.Notice(Fmt("Outgoing connection write error: %v", err))
return
}
log.Debug(Fmt("Outgoing connection wrote %v bytes", n))
log.Info(Fmt("Outgoing connection wrote %v bytes", n))
// Wait for data receipt
time.Sleep(1 * time.Second)
@ -83,7 +83,7 @@ func testHairpin(listener net.Listener, extAddr string) (supportsHairpin bool) {
}
func Probe() (caps UPNPCapabilities, err error) {
log.Debug("Probing for UPnP!")
log.Info("Probing for UPnP!")
intPort, extPort := 8001, 8001

4
rpc/client/client.go
View File

@ -22,7 +22,7 @@ func Call(remote string, method string, params []interface{}, dest interface{})
}
requestBytes := binary.JSONBytes(request)
requestBuf := bytes.NewBuffer(requestBytes)
log.Debug(Fmt("RPC request to %v: %v", remote, string(requestBytes)))
log.Info(Fmt("RPC request to %v: %v", remote, string(requestBytes)))
httpResponse, err := http.Post(remote, "text/json", requestBuf)
if err != nil {
return dest, err
@ -32,7 +32,7 @@ func Call(remote string, method string, params []interface{}, dest interface{})
if err != nil {
return dest, err
}
log.Debug(Fmt("RPC response: %v", string(responseBytes)))
log.Info(Fmt("RPC response: %v", string(responseBytes)))
// Parse response into JSONResponse
response := RPCResponse{}

2
rpc/core/blocks.go
View File

@ -18,7 +18,7 @@ func BlockchainInfo(minHeight, maxHeight int) (*ctypes.ResponseBlockchainInfo, e
if minHeight == 0 {
minHeight = MaxInt(1, maxHeight-20)
}
log.Debug("BlockchainInfoHandler", "maxHeight", maxHeight, "minHeight", minHeight)
log.Info("BlockchainInfoHandler", "maxHeight", maxHeight, "minHeight", minHeight)
blockMetas := []*types.BlockMeta{}
for height := maxHeight; height >= minHeight; height-- {

8
rpc/server/handlers.go
View File

@ -114,7 +114,7 @@ func makeJSONRPCHandler(funcMap map[string]*RPCFunc) http.HandlerFunc {
return
}
returns := rpcFunc.f.Call(args)
log.Debug("HTTPJSONRPC", "method", request.Method, "args", args, "returns", returns)
log.Info("HTTPJSONRPC", "method", request.Method, "args", args, "returns", returns)
response, err := unreflectResponse(returns)
if err != nil {
WriteRPCResponse(w, NewRPCResponse(nil, err.Error()))
@ -166,7 +166,7 @@ func makeHTTPHandler(rpcFunc *RPCFunc) func(http.ResponseWriter, *http.Request)
return
}
returns := rpcFunc.f.Call(args)
log.Debug("HTTPRestRPC", "method", r.URL.Path, "args", args, "returns", returns)
log.Info("HTTPRestRPC", "method", r.URL.Path, "args", args, "returns", returns)
response, err := unreflectResponse(returns)
if err != nil {
WriteRPCResponse(w, NewRPCResponse(nil, err.Error()))
@ -312,7 +312,7 @@ func (con *WSConnection) read() {
}
switch req.Type {
case "subscribe":
log.Info("New event subscription", "con id", con.id, "event", req.Event)
log.Notice("New event subscription", "con id", con.id, "event", req.Event)
con.evsw.AddListenerForEvent(con.id, req.Event, func(msg interface{}) {
resp := WSResponse{
Event: req.Event,
@ -388,7 +388,7 @@ func (wm *WebsocketManager) websocketHandler(w http.ResponseWriter, r *http.Requ
// register connection
con := NewWSConnection(wsConn)
log.Info("New websocket connection", "origin", con.id)
log.Notice("New websocket connection", "origin", con.id)
con.Start(wm.evsw)
}

4
rpc/server/http_server.go
View File

@ -17,7 +17,7 @@ import (
)
func StartHTTPServer(listenAddr string, handler http.Handler) (net.Listener, error) {
log.Info(Fmt("Starting RPC HTTP server on %v", listenAddr))
log.Notice(Fmt("Starting RPC HTTP server on %v", listenAddr))
listener, err := net.Listen("tcp", listenAddr)
if err != nil {
return nil, fmt.Errorf("Failed to listen to %v", listenAddr)
@ -84,7 +84,7 @@ func RecoverAndLogHandler(handler http.Handler) http.Handler {
if rww.Status == -1 {
rww.Status = 200
}
log.Debug("Served RPC HTTP response",
log.Info("Served RPC HTTP response",
"method", r.Method, "url", r.URL,
"status", rww.Status, "duration", durationMS,
"remoteAddr", r.RemoteAddr,

58
state/execution.go
View File

@ -119,7 +119,7 @@ func execBlock(s *State, block *types.Block, blockPartsHeader types.PartSetHeade
s.BondedValidators.Iterate(func(index int, val *Validator) bool {
lastActivityHeight := MaxInt(val.BondHeight, val.LastCommitHeight)
if lastActivityHeight+validatorTimeoutBlocks < block.Height {
log.Info("Validator timeout", "validator", val, "height", block.Height)
log.Notice("Validator timeout", "validator", val, "height", block.Height)
toTimeout = append(toTimeout, val)
}
return false
@ -359,7 +359,7 @@ func ExecTx(blockCache *BlockCache, tx types.Tx, runCall bool, evc events.Fireab
// Validate input
inAcc = blockCache.GetAccount(tx.Input.Address)
if inAcc == nil {
log.Debug(Fmt("Can't find in account %X", tx.Input.Address))
log.Info(Fmt("Can't find in account %X", tx.Input.Address))
return types.ErrTxInvalidAddress
}
@ -376,24 +376,24 @@ func ExecTx(blockCache *BlockCache, tx types.Tx, runCall bool, evc events.Fireab
// pubKey should be present in either "inAcc" or "tx.Input"
if err := checkInputPubKey(inAcc, tx.Input); err != nil {
log.Debug(Fmt("Can't find pubkey for %X", tx.Input.Address))
log.Info(Fmt("Can't find pubkey for %X", tx.Input.Address))
return err
}
signBytes := acm.SignBytes(_s.ChainID, tx)
err := validateInput(inAcc, signBytes, tx.Input)
if err != nil {
log.Debug(Fmt("validateInput failed on %X: %v", tx.Input.Address, err))
log.Info(Fmt("validateInput failed on %X: %v", tx.Input.Address, err))
return err
}
if tx.Input.Amount < tx.Fee {
log.Debug(Fmt("Sender did not send enough to cover the fee %X", tx.Input.Address))
log.Info(Fmt("Sender did not send enough to cover the fee %X", tx.Input.Address))
return types.ErrTxInsufficientFunds
}
if !createAccount {
// Validate output
if len(tx.Address) != 20 {
log.Debug(Fmt("Destination address is not 20 bytes %X", tx.Address))
log.Info(Fmt("Destination address is not 20 bytes %X", tx.Address))
return types.ErrTxInvalidAddress
}
// this may be nil if we are still in mempool and contract was created in same block as this tx
@ -403,7 +403,7 @@ func ExecTx(blockCache *BlockCache, tx types.Tx, runCall bool, evc events.Fireab
outAcc = blockCache.GetAccount(tx.Address)
}
log.Debug(Fmt("Out account: %v", outAcc))
log.Info(Fmt("Out account: %v", outAcc))
// Good!
value := tx.Input.Amount - tx.Fee
@ -445,22 +445,22 @@ func ExecTx(blockCache *BlockCache, tx types.Tx, runCall bool, evc events.Fireab
inAcc.Balance -= tx.Fee
blockCache.UpdateAccount(inAcc)
if outAcc == nil {
log.Debug(Fmt("Cannot find destination address %X. Deducting fee from caller", tx.Address))
log.Info(Fmt("Cannot find destination address %X. Deducting fee from caller", tx.Address))
} else {
log.Debug(Fmt("Attempting to call an account (%X) with no code. Deducting fee from caller", tx.Address))
log.Info(Fmt("Attempting to call an account (%X) with no code. Deducting fee from caller", tx.Address))
}
return types.ErrTxInvalidAddress
}
}
callee = toVMAccount(outAcc)
code = callee.Code
log.Debug(Fmt("Calling contract %X with code %X", callee.Address, callee.Code))
log.Info(Fmt("Calling contract %X with code %X", callee.Address, callee.Code))
} else {
callee = txCache.CreateAccount(caller)
log.Debug(Fmt("Created new account %X", callee.Address))
log.Info(Fmt("Created new account %X", callee.Address))
code = tx.Data
}
log.Debug(Fmt("Code for this contract: %X", code))
log.Info(Fmt("Code for this contract: %X", code))
txCache.UpdateAccount(caller) // because we bumped nonce
txCache.UpdateAccount(callee) // so the txCache knows about the callee and the create and/or transfer takes effect
@ -474,12 +474,12 @@ func ExecTx(blockCache *BlockCache, tx types.Tx, runCall bool, evc events.Fireab
if err != nil {
exception = err.Error()
// Failure. Charge the gas fee. The 'value' was otherwise not transferred.
log.Debug(Fmt("Error on execution: %v", err))
log.Info(Fmt("Error on execution: %v", err))
inAcc.Balance -= tx.Fee
blockCache.UpdateAccount(inAcc)
// Throw away 'txCache' which holds incomplete updates (don't sync it).
} else {
log.Debug("Successful execution")
log.Info("Successful execution")
// Success
if createAccount {
callee.Code = ret
@ -488,7 +488,7 @@ func ExecTx(blockCache *BlockCache, tx types.Tx, runCall bool, evc events.Fireab
txCache.Sync()
}
// Create a receipt from the ret and whether errored.
log.Info("VM call complete", "caller", caller, "callee", callee, "return", ret, "err", err)
log.Notice("VM call complete", "caller", caller, "callee", callee, "return", ret, "err", err)
// Fire Events for sender and receiver
// a separate event will be fired from vm for each additional call
@ -516,7 +516,7 @@ func ExecTx(blockCache *BlockCache, tx types.Tx, runCall bool, evc events.Fireab
// Validate input
inAcc = blockCache.GetAccount(tx.Input.Address)
if inAcc == nil {
log.Debug(Fmt("Can't find in account %X", tx.Input.Address))
log.Info(Fmt("Can't find in account %X", tx.Input.Address))
return types.ErrTxInvalidAddress
}
// check permission
@ -525,24 +525,24 @@ func ExecTx(blockCache *BlockCache, tx types.Tx, runCall bool, evc events.Fireab
}
// pubKey should be present in either "inAcc" or "tx.Input"
if err := checkInputPubKey(inAcc, tx.Input); err != nil {
log.Debug(Fmt("Can't find pubkey for %X", tx.Input.Address))
log.Info(Fmt("Can't find pubkey for %X", tx.Input.Address))
return err
}
signBytes := acm.SignBytes(_s.ChainID, tx)
err := validateInput(inAcc, signBytes, tx.Input)
if err != nil {
log.Debug(Fmt("validateInput failed on %X: %v", tx.Input.Address, err))
log.Info(Fmt("validateInput failed on %X: %v", tx.Input.Address, err))
return err
}
// fee is in addition to the amount which is used to determine the TTL
if tx.Input.Amount < tx.Fee {
log.Debug(Fmt("Sender did not send enough to cover the fee %X", tx.Input.Address))
log.Info(Fmt("Sender did not send enough to cover the fee %X", tx.Input.Address))
return types.ErrTxInsufficientFunds
}
// validate the input strings
if err := tx.ValidateStrings(); err != nil {
log.Debug(err.Error())
log.Info(err.Error())
return types.ErrTxInvalidString
}
@ -553,7 +553,7 @@ func ExecTx(blockCache *BlockCache, tx types.Tx, runCall bool, evc events.Fireab
expiresIn := int(value / costPerBlock)
lastBlockHeight := _s.LastBlockHeight
log.Debug("New NameTx", "value", value, "costPerBlock", costPerBlock, "expiresIn", expiresIn, "lastBlock", lastBlockHeight)
log.Info("New NameTx", "value", value, "costPerBlock", costPerBlock, "expiresIn", expiresIn, "lastBlock", lastBlockHeight)
// check if the name exists
entry := blockCache.GetNameRegEntry(tx.Name)
@ -564,7 +564,7 @@ func ExecTx(blockCache *BlockCache, tx types.Tx, runCall bool, evc events.Fireab
if entry.Expires > lastBlockHeight {
// ensure we are owner
if bytes.Compare(entry.Owner, tx.Input.Address) != 0 {
log.Debug(Fmt("Sender %X is trying to update a name (%s) for which he is not owner", tx.Input.Address, tx.Name))
log.Info(Fmt("Sender %X is trying to update a name (%s) for which he is not owner", tx.Input.Address, tx.Name))
return types.ErrIncorrectOwner
}
} else {
@ -575,7 +575,7 @@ func ExecTx(blockCache *BlockCache, tx types.Tx, runCall bool, evc events.Fireab
if value == 0 && len(tx.Data) == 0 {
// maybe we reward you for telling us we can delete this crap
// (owners if not expired, anyone if expired)
log.Debug("Removing namereg entry", "name", entry.Name)
log.Info("Removing namereg entry", "name", entry.Name)
blockCache.RemoveNameRegEntry(entry.Name)
} else {
// update the entry by bumping the expiry
@ -586,7 +586,7 @@ func ExecTx(blockCache *BlockCache, tx types.Tx, runCall bool, evc events.Fireab
}
entry.Expires = lastBlockHeight + expiresIn
entry.Owner = tx.Input.Address
log.Debug("An old namereg entry has expired and been reclaimed", "name", entry.Name, "expiresIn", expiresIn, "owner", entry.Owner)
log.Info("An old namereg entry has expired and been reclaimed", "name", entry.Name, "expiresIn", expiresIn, "owner", entry.Owner)
} else {
// since the size of the data may have changed
// we use the total amount of "credit"
@ -597,7 +597,7 @@ func ExecTx(blockCache *BlockCache, tx types.Tx, runCall bool, evc events.Fireab
return errors.New(Fmt("Names must be registered for at least %d blocks", types.MinNameRegistrationPeriod))
}
entry.Expires = lastBlockHeight + expiresIn
log.Debug("Updated namereg entry", "name", entry.Name, "expiresIn", expiresIn, "oldCredit", oldCredit, "value", value, "credit", credit)
log.Info("Updated namereg entry", "name", entry.Name, "expiresIn", expiresIn, "oldCredit", oldCredit, "value", value, "credit", credit)
}
entry.Data = tx.Data
blockCache.UpdateNameRegEntry(entry)
@ -613,7 +613,7 @@ func ExecTx(blockCache *BlockCache, tx types.Tx, runCall bool, evc events.Fireab
Data: tx.Data,
Expires: lastBlockHeight + expiresIn,
}
log.Debug("Creating namereg entry", "name", entry.Name, "expiresIn", expiresIn)
log.Info("Creating namereg entry", "name", entry.Name, "expiresIn", expiresIn)
blockCache.UpdateNameRegEntry(entry)
}
@ -824,14 +824,14 @@ func HasPermission(state AccountGetter, acc *acm.Account, perm ptypes.PermFlag)
v, err := acc.Permissions.Base.Get(perm)
if _, ok := err.(ptypes.ErrValueNotSet); ok {
log.Debug("Account does not have permission", "account", acc, "accPermissions", acc.Permissions, "perm", perm)
log.Info("Account does not have permission", "account", acc, "accPermissions", acc.Permissions, "perm", perm)
if state == nil {
panic("All known global permissions should be set!")
}
log.Debug("Querying GlobalPermissionsAddress")
log.Info("Querying GlobalPermissionsAddress")
return HasPermission(nil, state.GetAccount(ptypes.GlobalPermissionsAddress), perm)
} else {
log.Debug("Account has permission", "account", acc, "accPermissions", acc.Permissions, "perm", perm)
log.Info("Account has permission", "account", acc, "accPermissions", acc.Permissions, "perm", perm)
}
return v
}