From e087284a4f42014d6ddc67314fcf1aefdc648b4d Mon Sep 17 00:00:00 2001 From: Ethan Buchman Date: Sun, 19 Jul 2015 21:15:45 +0000 Subject: [PATCH 1/3] update logger package for new level 'notice' --- Godeps/Godeps.json | 4 ++-- .../src/github.com/tendermint/log15/format.go | 4 +++- .../src/github.com/tendermint/log15/logger.go | 10 ++++++++++ .../_workspace/src/github.com/tendermint/log15/root.go | 5 +++++ .../src/github.com/tendermint/log15/syslog.go | 2 ++ node/node.go | 3 ++- p2p/switch.go | 4 ++-- 7 files changed, 26 insertions(+), 6 deletions(-) diff --git a/Godeps/Godeps.json b/Godeps/Godeps.json index bcb14f4f..dbf9058b 100644 --- a/Godeps/Godeps.json +++ b/Godeps/Godeps.json @@ -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", diff --git a/Godeps/_workspace/src/github.com/tendermint/log15/format.go b/Godeps/_workspace/src/github.com/tendermint/log15/format.go index 6ea8c81b..740433b3 100644 --- a/Godeps/_workspace/src/github.com/tendermint/log15/format.go +++ b/Godeps/_workspace/src/github.com/tendermint/log15/format.go @@ -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 } diff --git a/Godeps/_workspace/src/github.com/tendermint/log15/logger.go b/Godeps/_workspace/src/github.com/tendermint/log15/logger.go index dcd7cf8d..99b91876 100644 --- a/Godeps/_workspace/src/github.com/tendermint/log15/logger.go +++ b/Godeps/_workspace/src/github.com/tendermint/log15/logger.go @@ -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) } diff --git a/Godeps/_workspace/src/github.com/tendermint/log15/root.go b/Godeps/_workspace/src/github.com/tendermint/log15/root.go index 85fd1f03..fc3c2308 100644 --- a/Godeps/_workspace/src/github.com/tendermint/log15/root.go +++ b/Godeps/_workspace/src/github.com/tendermint/log15/root.go @@ -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) diff --git a/Godeps/_workspace/src/github.com/tendermint/log15/syslog.go b/Godeps/_workspace/src/github.com/tendermint/log15/syslog.go index 36c12b11..4b16e2b2 100644 --- a/Godeps/_workspace/src/github.com/tendermint/log15/syslog.go +++ b/Godeps/_workspace/src/github.com/tendermint/log15/syslog.go @@ -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: diff --git a/node/node.go b/node/node.go index 49ed65d3..f3f8aacd 100644 --- a/node/node.go +++ b/node/node.go @@ -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) @@ -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() diff --git a/p2p/switch.go b/p2p/switch.go index 0ea29fab..e642a27b 100644 --- a/p2p/switch.go +++ b/p2p/switch.go @@ -338,7 +338,7 @@ 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.Debug("Ignoring inbound connection: already have enough peers", "address", inConn.RemoteAddr().String(), "numPeers", sw.peers.Size(), "max", maxNumPeers) continue } @@ -351,7 +351,7 @@ func (sw *Switch) listenerRoutine(l Listener) { // New inbound connection! _, err := sw.AddPeerWithConnection(inConn, false) if err != nil { - log.Info("Ignoring inbound connection: error on AddPeerWithConnection", "conn", inConn, "error", err) + log.Info("Ignoring inbound connection: error on AddPeerWithConnection", "address", inConn.RemoteAddr().String(), "error", err) continue } From bb4ca1407f2f3e3eae2cab94773aa758e2ece941 Mon Sep 17 00:00:00 2001 From: Ethan Buchman Date: Sun, 19 Jul 2015 21:49:13 +0000 Subject: [PATCH 2/3] info->notice, debug->info --- binary/reflect.go | 58 +++++++++---------- binary/reflect_test.go | 4 +- blockchain/pool.go | 8 +-- blockchain/pool_test.go | 8 +-- blockchain/reactor.go | 14 ++--- cmd/barak/main.go | 2 +- cmd/barak/validate.go | 4 +- cmd/tendermint/reset_priv_validator.go | 4 +- consensus/height_vote_set.go | 4 +- consensus/reactor.go | 56 +++++++++--------- consensus/state.go | 80 +++++++++++++------------- mempool/mempool.go | 16 +++--- mempool/reactor.go | 10 ++-- node/node.go | 10 ++-- p2p/addrbook.go | 18 +++--- p2p/connection.go | 28 ++++----- p2p/listener.go | 12 ++-- p2p/peer.go | 6 +- p2p/pex_reactor.go | 14 ++--- p2p/switch.go | 24 ++++---- p2p/upnp/probe.go | 22 +++---- rpc/client/client.go | 4 +- rpc/core/blocks.go | 2 +- rpc/server/handlers.go | 8 +-- rpc/server/http_server.go | 4 +- state/execution.go | 58 +++++++++---------- 26 files changed, 239 insertions(+), 239 deletions(-) diff --git a/binary/reflect.go b/binary/reflect.go index c54116af..25cf730c 100644 --- a/binary/reflect.go +++ b/binary/reflect.go @@ -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) diff --git a/binary/reflect_test.go b/binary/reflect_test.go index b2a37c6b..6195fb90 100644 --- a/binary/reflect_test.go +++ b/binary/reflect_test.go @@ -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() diff --git a/blockchain/pool.go b/blockchain/pool.go index e748252a..72f8f3c4 100644 --- a/blockchain/pool.go +++ b/blockchain/pool.go @@ -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 } diff --git a/blockchain/pool_test.go b/blockchain/pool_test.go index e6ff3be4..ec587cac 100644 --- a/blockchain/pool_test.go +++ b/blockchain/pool_test.go @@ -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) } } diff --git a/blockchain/reactor.go b/blockchain/reactor.go index 8ed185af..83dba679 100644 --- a/blockchain/reactor.go +++ b/blockchain/reactor.go @@ -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 { diff --git a/cmd/barak/main.go b/cmd/barak/main.go index 92315ae5..c2e64e6c 100644 --- a/cmd/barak/main.go +++ b/cmd/barak/main.go @@ -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: diff --git a/cmd/barak/validate.go b/cmd/barak/validate.go index 9653f732..9533fff5 100644 --- a/cmd/barak/validate.go +++ b/cmd/barak/validate.go @@ -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 diff --git a/cmd/tendermint/reset_priv_validator.go b/cmd/tendermint/reset_priv_validator.go index eedbc03b..3a0c46d5 100644 --- a/cmd/tendermint/reset_priv_validator.go +++ b/cmd/tendermint/reset_priv_validator.go @@ -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) } } diff --git a/consensus/height_vote_set.go b/consensus/height_vote_set.go index 42e89074..52c0b8a4 100644 --- a/consensus/height_vote_set.go +++ b/consensus/height_vote_set.go @@ -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 diff --git a/consensus/reactor.go b/consensus/reactor.go index f357987b..c9ba3372 100644 --- a/consensus/reactor.go +++ b/consensus/reactor.go @@ -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,7 +133,7 @@ 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) + log.Info("Receive", "channel", chId, "peer", peer, "bytes", msgBytes) if !conR.IsRunning() { 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.Info("Receive", "channel", chId, "peer", peer, "msg", msg, "rsHeight", rs.Height) //, "bytes", msgBytes) 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() @@ -471,7 +471,7 @@ OUTER_LOOP: sleeping = 0 } - log.Debug("gossipVotesRoutine", "rsHeight", rs.Height, "rsRound", rs.Round, + log.Info("gossipVotesRoutine", "rsHeight", rs.Height, "rsRound", rs.Round, "prsHeight", prs.Height, "prsRound", prs.Round, "prsStep", prs.Step) // If height matches, then send LastCommit, Prevotes, Precommits. @@ -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 { diff --git a/consensus/state.go b/consensus/state.go index 9ecf0fae..85e8da20 100644 --- a/consensus/state.go +++ b/consensus/state.go @@ -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) diff --git a/mempool/mempool.go b/mempool/mempool.go index a08d9bc6..e0e09f04 100644 --- a/mempool/mempool.go +++ b/mempool/mempool.go @@ -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 } diff --git a/mempool/reactor.go b/mempool/reactor.go index 327eef51..440a0450 100644 --- a/mempool/reactor.go +++ b/mempool/reactor.go @@ -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. diff --git a/node/node.go b/node/node.go index f3f8aacd..b6d05f7e 100644 --- a/node/node.go +++ b/node/node.go @@ -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 @@ -154,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() @@ -171,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()) } @@ -199,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) } } diff --git a/p2p/addrbook.go b/p2p/addrbook.go index f1f17851..d6d21775 100644 --- a/p2p/addrbook.go +++ b/p2p/addrbook.go @@ -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 } diff --git a/p2p/connection.go b/p2p/connection.go index 3e872d52..c3219795 100644 --- a/p2p/connection.go +++ b/p2p/connection.go @@ -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() @@ -151,7 +151,7 @@ func (c *MConnection) String() string { } func (c *MConnection) flush() { - log.Debug("Flush", "conn", c) + log.Info("Flush", "conn", c) err := c.bufWriter.Flush() if err != nil { log.Warn("MConnection flush failed", "error", err) @@ -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) @@ -426,7 +426,7 @@ FOR_LOOP: break FOR_LOOP } if msgBytes != nil { - log.Debug("Received bytes", "chId", pkt.ChannelId, "msgBytes", msgBytes) + log.Info("Received bytes", "chId", pkt.ChannelId, "msgBytes", msgBytes) c.onReceive(pkt.ChannelId, msgBytes) } default: @@ -565,7 +565,7 @@ func (ch *Channel) nextMsgPacket() msgPacket { // Not goroutine-safe func (ch *Channel) writeMsgPacketTo(w io.Writer) (n int64, err error) { packet := ch.nextMsgPacket() - log.Debug("Write Msg Packet", "conn", ch.conn, "packet", packet) + log.Info("Write Msg Packet", "conn", ch.conn, "packet", packet) binary.WriteByte(packetTypeMsg, w, &n, &err) binary.WriteBinary(packet, w, &n, &err) if err != nil { @@ -577,7 +577,7 @@ func (ch *Channel) writeMsgPacketTo(w io.Writer) (n int64, err error) { // Handles incoming msgPackets. Returns a msg bytes if msg is complete. // Not goroutine-safe func (ch *Channel) recvMsgPacket(packet msgPacket) ([]byte, error) { - log.Debug("Read Msg Packet", "conn", ch.conn, "packet", packet) + log.Info("Read Msg Packet", "conn", ch.conn, "packet", packet) if binary.MaxBinaryReadSize < len(ch.recving)+len(packet.Bytes) { return nil, binary.ErrBinaryReadSizeOverflow } diff --git a/p2p/listener.go b/p2p/listener.go index f69422b1..86ccd753 100644 --- a/p2p/listener.go +++ b/p2p/listener.go @@ -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)) } diff --git a/p2p/peer.go b/p2p/peer.go index a17e700e..776e1f66 100644 --- a/p2p/peer.go +++ b/p2p/peer.go @@ -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() } } diff --git a/p2p/pex_reactor.go b/p2p/pex_reactor.go index f3d84423..4ffb5f43 100644 --- a/p2p/pex_reactor.go +++ b/p2p/pex_reactor.go @@ -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) } } diff --git a/p2p/switch.go b/p2p/switch.go index e642a27b..9325a12b 100644 --- a/p2p/switch.go +++ b/p2p/switch.go @@ -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", "address", inConn.RemoteAddr().String(), "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", "address", inConn.RemoteAddr().String(), "error", err) + log.Notice("Ignoring inbound connection: error on AddPeerWithConnection", "address", inConn.RemoteAddr().String(), "error", err) continue } diff --git a/p2p/upnp/probe.go b/p2p/upnp/probe.go index 6636c887..3f9f8ad9 100644 --- a/p2p/upnp/probe.go +++ b/p2p/upnp/probe.go @@ -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 diff --git a/rpc/client/client.go b/rpc/client/client.go index 94b8d193..aa756601 100644 --- a/rpc/client/client.go +++ b/rpc/client/client.go @@ -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{} diff --git a/rpc/core/blocks.go b/rpc/core/blocks.go index 90119bb7..4809bf54 100644 --- a/rpc/core/blocks.go +++ b/rpc/core/blocks.go @@ -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-- { diff --git a/rpc/server/handlers.go b/rpc/server/handlers.go index 58e8db08..8869a5c9 100644 --- a/rpc/server/handlers.go +++ b/rpc/server/handlers.go @@ -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) } diff --git a/rpc/server/http_server.go b/rpc/server/http_server.go index d2e4cc4b..899365db 100644 --- a/rpc/server/http_server.go +++ b/rpc/server/http_server.go @@ -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, diff --git a/state/execution.go b/state/execution.go index a823e1d2..4e41df16 100644 --- a/state/execution.go +++ b/state/execution.go @@ -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 } From a28d9249660348c11635844e7c7a4f07ac162009 Mon Sep 17 00:00:00 2001 From: Ethan Buchman Date: Sun, 19 Jul 2015 22:02:06 +0000 Subject: [PATCH 3/3] move some logs to debug --- consensus/reactor.go | 6 +++--- p2p/connection.go | 8 ++++---- 2 files changed, 7 insertions(+), 7 deletions(-) diff --git a/consensus/reactor.go b/consensus/reactor.go index c9ba3372..a5f21aeb 100644 --- a/consensus/reactor.go +++ b/consensus/reactor.go @@ -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.Info("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.Info("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: @@ -471,7 +471,7 @@ OUTER_LOOP: sleeping = 0 } - log.Info("gossipVotesRoutine", "rsHeight", rs.Height, "rsRound", rs.Round, + log.Debug("gossipVotesRoutine", "rsHeight", rs.Height, "rsRound", rs.Round, "prsHeight", prs.Height, "prsRound", prs.Round, "prsStep", prs.Step) // If height matches, then send LastCommit, Prevotes, Precommits. diff --git a/p2p/connection.go b/p2p/connection.go index c3219795..c095c166 100644 --- a/p2p/connection.go +++ b/p2p/connection.go @@ -151,7 +151,7 @@ func (c *MConnection) String() string { } func (c *MConnection) flush() { - log.Info("Flush", "conn", c) + log.Debug("Flush", "conn", c) err := c.bufWriter.Flush() if err != nil { log.Warn("MConnection flush failed", "error", err) @@ -426,7 +426,7 @@ FOR_LOOP: break FOR_LOOP } if msgBytes != nil { - log.Info("Received bytes", "chId", pkt.ChannelId, "msgBytes", msgBytes) + log.Debug("Received bytes", "chId", pkt.ChannelId, "msgBytes", msgBytes) c.onReceive(pkt.ChannelId, msgBytes) } default: @@ -565,7 +565,7 @@ func (ch *Channel) nextMsgPacket() msgPacket { // Not goroutine-safe func (ch *Channel) writeMsgPacketTo(w io.Writer) (n int64, err error) { packet := ch.nextMsgPacket() - log.Info("Write Msg Packet", "conn", ch.conn, "packet", packet) + log.Debug("Write Msg Packet", "conn", ch.conn, "packet", packet) binary.WriteByte(packetTypeMsg, w, &n, &err) binary.WriteBinary(packet, w, &n, &err) if err != nil { @@ -577,7 +577,7 @@ func (ch *Channel) writeMsgPacketTo(w io.Writer) (n int64, err error) { // Handles incoming msgPackets. Returns a msg bytes if msg is complete. // Not goroutine-safe func (ch *Channel) recvMsgPacket(packet msgPacket) ([]byte, error) { - log.Info("Read Msg Packet", "conn", ch.conn, "packet", packet) + log.Debug("Read Msg Packet", "conn", ch.conn, "packet", packet) if binary.MaxBinaryReadSize < len(ch.recving)+len(packet.Bytes) { return nil, binary.ErrBinaryReadSizeOverflow }