From 688d118c7e0d439691e84fc6e068ab3e19da5185 Mon Sep 17 00:00:00 2001 From: obscuren Date: Tue, 7 Apr 2015 14:57:04 +0200 Subject: [PATCH] Updated logging --- blockpool/blockpool.go | 3 ++- cmd/utils/cmd.go | 8 ++++---- cmd/utils/flags.go | 7 +++++++ core/chain_manager.go | 10 +++++----- eth/backend.go | 14 +++++++------- eth/protocol_test.go | 4 ++-- logger/glog/glog.go | 4 ++++ logger/glog/glog_file.go | 4 ++++ miner/worker.go | 17 +++++++++++------ p2p/discover/udp.go | 19 +++++++++---------- p2p/nat/nat.go | 13 ++++++------- p2p/server.go | 24 ++++++++++++------------ whisper/whisper.go | 7 +++---- 13 files changed, 76 insertions(+), 58 deletions(-) diff --git a/blockpool/blockpool.go b/blockpool/blockpool.go index 00dad3330..3b3de928d 100644 --- a/blockpool/blockpool.go +++ b/blockpool/blockpool.go @@ -12,6 +12,7 @@ import ( "github.com/ethereum/go-ethereum/errs" "github.com/ethereum/go-ethereum/event" ethlogger "github.com/ethereum/go-ethereum/logger" + "github.com/ethereum/go-ethereum/logger/glog" "github.com/ethereum/go-ethereum/pow" ) @@ -260,7 +261,7 @@ func (self *BlockPool) Start() { } } }() - plog.Infoln("Started") + glog.V(ethlogger.Info).Infoln("Blockpool started") } func (self *BlockPool) Stop() { diff --git a/cmd/utils/cmd.go b/cmd/utils/cmd.go index feea29d64..a6140d233 100644 --- a/cmd/utils/cmd.go +++ b/cmd/utils/cmd.go @@ -33,10 +33,10 @@ import ( "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/eth" "github.com/ethereum/go-ethereum/logger" + "github.com/ethereum/go-ethereum/logger/glog" "github.com/ethereum/go-ethereum/rlp" ) -var clilogger = logger.NewLogger("CLI") var interruptCallbacks = []func(os.Signal){} // Register interrupt handlers callbacks @@ -50,7 +50,7 @@ func HandleInterrupt() { go func() { signal.Notify(c, os.Interrupt) for sig := range c { - clilogger.Errorf("Shutting down (%v) ... \n", sig) + glog.V(logger.Error).Infof("Shutting down (%v) ... \n", sig) RunInterruptCallbacks(sig) } }() @@ -113,7 +113,7 @@ func Fatalf(format string, args ...interface{}) { } func StartEthereum(ethereum *eth.Ethereum) { - clilogger.Infoln("Starting ", ethereum.Name()) + glog.V(logger.Info).Infoln("Starting ", ethereum.Name()) if err := ethereum.Start(); err != nil { exit(err) } @@ -124,7 +124,7 @@ func StartEthereum(ethereum *eth.Ethereum) { } func StartEthereumForTest(ethereum *eth.Ethereum) { - clilogger.Infoln("Starting ", ethereum.Name()) + glog.V(logger.Info).Infoln("Starting ", ethereum.Name()) ethereum.StartForTest() RegisterInterrupt(func(sig os.Signal) { ethereum.Stop() diff --git a/cmd/utils/flags.go b/cmd/utils/flags.go index 0609bcf75..51844a68e 100644 --- a/cmd/utils/flags.go +++ b/cmd/utils/flags.go @@ -194,6 +194,11 @@ var ( Name: "logtostderr", Usage: "Logs are written to standard error instead of to files.", } + LogVModuleFlag = cli.GenericFlag{ + Name: "vmodule", + Usage: "The syntax of the argument is a comma-separated list of pattern=N, where pattern is a literal file name (minus the \".go\" suffix) or \"glob\" pattern and N is a V level.", + Value: glog.GetVModule(), + } ) func GetNAT(ctx *cli.Context) nat.Interface { @@ -227,6 +232,8 @@ func MakeEthConfig(clientID, version string, ctx *cli.Context) *eth.Config { glog.SetV(ctx.GlobalInt(LogLevelFlag.Name)) // Set the log type glog.SetToStderr(ctx.GlobalBool(LogToStdErrFlag.Name)) + // Set the log dir + glog.SetLogDir(ctx.GlobalString(LogFileFlag.Name)) return ð.Config{ Name: common.MakeName(clientID, version), diff --git a/core/chain_manager.go b/core/chain_manager.go index c2e241e90..3ab95d272 100644 --- a/core/chain_manager.go +++ b/core/chain_manager.go @@ -452,7 +452,7 @@ func (self *ChainManager) InsertChain(chain types.Blocks) error { var ( queue = make([]interface{}, len(chain)) queueEvent = queueEvent{queue: queue} - stats struct{ delayed, processed int } + stats struct{ queued, processed int } tstart = time.Now() ) for i, block := range chain { @@ -472,13 +472,13 @@ func (self *ChainManager) InsertChain(chain types.Blocks) error { // future block for future use if err == BlockFutureErr { self.futureBlocks.Push(block) - stats.delayed++ + stats.queued++ continue } if IsParentErr(err) && self.futureBlocks.Has(block.ParentHash()) { self.futureBlocks.Push(block) - stats.delayed++ + stats.queued++ continue } @@ -545,10 +545,10 @@ func (self *ChainManager) InsertChain(chain types.Blocks) error { } - if (stats.delayed > 0 || stats.processed > 0) && bool(glog.V(logger.Info)) { + if (stats.queued > 0 || stats.processed > 0) && bool(glog.V(logger.Info)) { tend := time.Since(tstart) start, end := chain[0], chain[len(chain)-1] - glog.Infof("imported %d block(s) %d delayed in %v. #%v [%x / %x]\n", stats.processed, stats.delayed, tend, end.Number(), start.Hash().Bytes()[:4], end.Hash().Bytes()[:4]) + glog.Infof("imported %d block(s) %d queued in %v. #%v [%x / %x]\n", stats.processed, stats.queued, tend, end.Number(), start.Hash().Bytes()[:4], end.Hash().Bytes()[:4]) } go self.eventMux.Post(queueEvent) diff --git a/eth/backend.go b/eth/backend.go index ffc970212..6b60af1f1 100644 --- a/eth/backend.go +++ b/eth/backend.go @@ -18,6 +18,7 @@ import ( "github.com/ethereum/go-ethereum/ethdb" "github.com/ethereum/go-ethereum/event" "github.com/ethereum/go-ethereum/logger" + "github.com/ethereum/go-ethereum/logger/glog" "github.com/ethereum/go-ethereum/miner" "github.com/ethereum/go-ethereum/p2p" "github.com/ethereum/go-ethereum/p2p/discover" @@ -26,7 +27,6 @@ import ( ) var ( - servlogger = logger.NewLogger("SERV") jsonlogger = logger.NewJsonLogger() defaultBootNodes = []*discover.Node{ @@ -83,7 +83,7 @@ func (cfg *Config) parseBootNodes() []*discover.Node { } n, err := discover.ParseNode(url) if err != nil { - servlogger.Errorf("Bootstrap URL %s: %v\n", url, err) + glog.V(logger.Error).Infof("Bootstrap URL %s: %v\n", url, err) continue } ns = append(ns, n) @@ -107,7 +107,7 @@ func (cfg *Config) nodeKey() (*ecdsa.PrivateKey, error) { return nil, fmt.Errorf("could not generate server key: %v", err) } if err := ioutil.WriteFile(keyfile, crypto.FromECDSA(key), 0600); err != nil { - servlogger.Errorln("could not persist nodekey: ", err) + glog.V(logger.Error).Infoln("could not persist nodekey: ", err) } return key, nil } @@ -177,7 +177,7 @@ func New(config *Config) (*Ethereum, error) { return nil, fmt.Errorf("Database version mismatch. Protocol(%d / %d). `rm -rf %s`", protov, config.ProtocolVersion, path) } saveProtocolVersion(blockDb, config.ProtocolVersion) - servlogger.Infof("Protocol Version: %v, Network Id: %v", config.ProtocolVersion, config.NetworkId) + glog.V(logger.Info).Infof("Protocol Version: %v, Network Id: %v", config.ProtocolVersion, config.NetworkId) eth := &Ethereum{ shutdownChan: make(chan bool), @@ -303,7 +303,7 @@ func (s *Ethereum) StartMining() error { eb, err := s.Etherbase() if err != nil { err = fmt.Errorf("Cannot start mining without etherbase address: %v", err) - servlogger.Errorln(err) + glog.V(logger.Error).Infoln(err) return err } @@ -380,7 +380,7 @@ func (s *Ethereum) Start() error { s.blockSub = s.eventMux.Subscribe(core.ChainHeadEvent{}) go s.blockBroadcastLoop() - servlogger.Infoln("Server started") + glog.V(logger.Info).Infoln("Server started") return nil } @@ -420,7 +420,7 @@ func (s *Ethereum) Stop() { s.whisper.Stop() } - servlogger.Infoln("Server stopped") + glog.V(logger.Info).Infoln("Server stopped") close(s.shutdownChan) } diff --git a/eth/protocol_test.go b/eth/protocol_test.go index d3466326a..7c724f7a7 100644 --- a/eth/protocol_test.go +++ b/eth/protocol_test.go @@ -250,7 +250,7 @@ func TestNewBlockMsg(t *testing.T) { var delay = 1 * time.Second // eth.reset() - block := types.NewBlock(common.Hash{1}, common.Address{1}, common.Hash{1}, common.Big1, 1, "extra") + block := types.NewBlock(common.Hash{1}, common.Address{1}, common.Hash{1}, common.Big1, 1, []byte("extra")) go p2p.Send(eth, NewBlockMsg, &newBlockMsgData{Block: block}) timer := time.After(delay) @@ -315,7 +315,7 @@ func TestBlockMsg(t *testing.T) { var delay = 3 * time.Second // eth.reset() newblock := func(i int64) *types.Block { - return types.NewBlock(common.Hash{byte(i)}, common.Address{byte(i)}, common.Hash{byte(i)}, big.NewInt(i), uint64(i), string(i)) + return types.NewBlock(common.Hash{byte(i)}, common.Address{byte(i)}, common.Hash{byte(i)}, big.NewInt(i), uint64(i), []byte{byte(i)}) } b := newblock(0) b.Header().Difficulty = nil // check if nil as *big.Int decodes as 0 diff --git a/logger/glog/glog.go b/logger/glog/glog.go index a0c4727f8..008c0e036 100644 --- a/logger/glog/glog.go +++ b/logger/glog/glog.go @@ -128,6 +128,10 @@ func GetTraceLocation() *TraceLocation { return &logging.traceLocation } +func GetVModule() *moduleSpec { + return &logging.vmodule +} + // get returns the value of the severity. func (s *severity) get() severity { return severity(atomic.LoadInt32((*int32)(s))) diff --git a/logger/glog/glog_file.go b/logger/glog/glog_file.go index 847e9b07c..2fc96eb4e 100644 --- a/logger/glog/glog_file.go +++ b/logger/glog/glog_file.go @@ -40,6 +40,10 @@ var logDirs []string //var logDir = flag.String("log_dir", "", "If non-empty, write log files in this directory") var logDir *string = new(string) +func SetLogDir(str string) { + *logDir = str +} + func createLogDirs() { if *logDir != "" { logDirs = append(logDirs, *logDir) diff --git a/miner/worker.go b/miner/worker.go index ffd4af7d3..8613df1c0 100644 --- a/miner/worker.go +++ b/miner/worker.go @@ -276,12 +276,12 @@ gasLimit: self.chain.TxState().RemoveNonce(from, tx.Nonce()) remove = append(remove, tx) - if glog.V(logger.Info) { + if glog.V(logger.Debug) { glog.Infof("TX (%x) failed, will be removed: %v\n", tx.Hash().Bytes()[:4], err) + glog.Infoln(tx) } - glog.V(logger.Debug).Infoln(tx) case state.IsGasLimitErr(err): - glog.V(logger.Info).Infof("Gas limit reached for block. %d TXs included in this block\n", i) + glog.V(logger.Debug).Infof("Gas limit reached for block. %d TXs included in this block\n", i) // Break on gas limit break gasLimit default: @@ -300,15 +300,20 @@ gasLimit: } if err := self.commitUncle(uncle.Header()); err != nil { - glog.V(logger.Info).Infof("Bad uncle found and will be removed (%x)\n", hash[:4]) + glog.V(logger.Debug).Infof("Bad uncle found and will be removed (%x)\n", hash[:4]) glog.V(logger.Debug).Infoln(uncle) badUncles = append(badUncles, hash) } else { - glog.V(logger.Info).Infof("commiting %x as uncle\n", hash[:4]) + glog.V(logger.Debug).Infof("commiting %x as uncle\n", hash[:4]) uncles = append(uncles, uncle.Header()) } } - glog.V(logger.Info).Infof("commit new work on block %v with %d txs & %d uncles\n", self.current.block.Number(), tcount, len(uncles)) + + // We only care about logging if we're actually mining + if atomic.LoadInt64(&self.mining) == 1 { + glog.V(logger.Info).Infof("commit new work on block %v with %d txs & %d uncles\n", self.current.block.Number(), tcount, len(uncles)) + } + for _, hash := range badUncles { delete(self.possibleUncles, hash) } diff --git a/p2p/discover/udp.go b/p2p/discover/udp.go index e9ede1397..a638a8f35 100644 --- a/p2p/discover/udp.go +++ b/p2p/discover/udp.go @@ -10,12 +10,11 @@ import ( "github.com/ethereum/go-ethereum/crypto" "github.com/ethereum/go-ethereum/logger" + "github.com/ethereum/go-ethereum/logger/glog" "github.com/ethereum/go-ethereum/p2p/nat" "github.com/ethereum/go-ethereum/rlp" ) -var log = logger.NewLogger("P2P Discovery") - const Version = 3 // Errors @@ -155,7 +154,7 @@ func ListenUDP(priv *ecdsa.PrivateKey, laddr string, natm nat.Interface) (*Table return nil, err } tab, _ := newUDP(priv, conn, natm) - log.Infoln("Listening,", tab.self) + glog.V(logger.Info).Infoln("Listening,", tab.self) return tab, nil } @@ -336,9 +335,9 @@ func (t *udp) send(toaddr *net.UDPAddr, ptype byte, req interface{}) error { if err != nil { return err } - log.DebugDetailf(">>> %v %T %v\n", toaddr, req, req) + glog.V(logger.Detail).Infof(">>> %v %T %v\n", toaddr, req, req) if _, err = t.conn.WriteToUDP(packet, toaddr); err != nil { - log.DebugDetailln("UDP send failed:", err) + glog.V(logger.Detail).Infoln("UDP send failed:", err) } return err } @@ -348,13 +347,13 @@ func encodePacket(priv *ecdsa.PrivateKey, ptype byte, req interface{}) ([]byte, b.Write(headSpace) b.WriteByte(ptype) if err := rlp.Encode(b, req); err != nil { - log.Errorln("error encoding packet:", err) + glog.V(logger.Error).Infoln("error encoding packet:", err) return nil, err } packet := b.Bytes() sig, err := crypto.Sign(crypto.Sha3(packet[headSize:]), priv) if err != nil { - log.Errorln("could not sign packet:", err) + glog.V(logger.Error).Infoln("could not sign packet:", err) return nil, err } copy(packet[macSize:], sig) @@ -376,13 +375,13 @@ func (t *udp) readLoop() { } packet, fromID, hash, err := decodePacket(buf[:nbytes]) if err != nil { - log.Debugf("Bad packet from %v: %v\n", from, err) + glog.V(logger.Debug).Infof("Bad packet from %v: %v\n", from, err) continue } - log.DebugDetailf("<<< %v %T %v\n", from, packet, packet) + glog.V(logger.Detail).Infof("<<< %v %T %v\n", from, packet, packet) go func() { if err := packet.handle(t, from, fromID, hash); err != nil { - log.Debugf("error handling %T from %v: %v", packet, from, err) + glog.V(logger.Debug).Infof("error handling %T from %v: %v", packet, from, err) } }() } diff --git a/p2p/nat/nat.go b/p2p/nat/nat.go index 12d355ba1..4ae7e6b17 100644 --- a/p2p/nat/nat.go +++ b/p2p/nat/nat.go @@ -10,11 +10,10 @@ import ( "time" "github.com/ethereum/go-ethereum/logger" + "github.com/ethereum/go-ethereum/logger/glog" "github.com/jackpal/go-nat-pmp" ) -var log = logger.NewLogger("P2P NAT") - // An implementation of nat.Interface can map local ports to ports // accessible from the Internet. type Interface interface { @@ -87,12 +86,12 @@ func Map(m Interface, c chan struct{}, protocol string, extport, intport int, na refresh := time.NewTimer(mapUpdateInterval) defer func() { refresh.Stop() - log.Debugf("Deleting port mapping: %s %d -> %d (%s) using %s\n", protocol, extport, intport, name, m) + glog.V(logger.Debug).Infof("Deleting port mapping: %s %d -> %d (%s) using %s\n", protocol, extport, intport, name, m) m.DeleteMapping(protocol, extport, intport) }() - log.Debugf("add mapping: %s %d -> %d (%s) using %s\n", protocol, extport, intport, name, m) + glog.V(logger.Debug).Infof("add mapping: %s %d -> %d (%s) using %s\n", protocol, extport, intport, name, m) if err := m.AddMapping(protocol, intport, extport, name, mapTimeout); err != nil { - log.Errorf("mapping error: %v\n", err) + glog.V(logger.Error).Infof("mapping error: %v\n", err) } for { select { @@ -101,9 +100,9 @@ func Map(m Interface, c chan struct{}, protocol string, extport, intport int, na return } case <-refresh.C: - log.DebugDetailf("refresh mapping: %s %d -> %d (%s) using %s\n", protocol, extport, intport, name, m) + glog.V(logger.Detail).Infof("refresh mapping: %s %d -> %d (%s) using %s\n", protocol, extport, intport, name, m) if err := m.AddMapping(protocol, intport, extport, name, mapTimeout); err != nil { - log.Errorf("mapping error: %v\n", err) + glog.V(logger.Error).Infof("mapping error: %v\n", err) } refresh.Reset(mapUpdateInterval) } diff --git a/p2p/server.go b/p2p/server.go index 813b0676f..0a2621aa8 100644 --- a/p2p/server.go +++ b/p2p/server.go @@ -10,6 +10,7 @@ import ( "time" "github.com/ethereum/go-ethereum/logger" + "github.com/ethereum/go-ethereum/logger/glog" "github.com/ethereum/go-ethereum/p2p/discover" "github.com/ethereum/go-ethereum/p2p/nat" "github.com/ethereum/go-ethereum/rlp" @@ -29,7 +30,6 @@ const ( frameWriteTimeout = 5 * time.Second ) -var srvlog = logger.NewLogger("P2P Server") var srvjslog = logger.NewJsonLogger() // Server manages all peer connections. @@ -161,7 +161,7 @@ func (srv *Server) Start() (err error) { if srv.running { return errors.New("server already running") } - srvlog.Infoln("Starting Server") + glog.V(logger.Info).Infoln("Starting Server") // static fields if srv.PrivateKey == nil { @@ -204,7 +204,7 @@ func (srv *Server) Start() (err error) { go srv.dialLoop() } if srv.NoDial && srv.ListenAddr == "" { - srvlog.Warnln("I will be kind-of useless, neither dialing nor listening.") + glog.V(logger.Warn).Infoln("I will be kind-of useless, neither dialing nor listening.") } srv.running = true @@ -242,7 +242,7 @@ func (srv *Server) Stop() { srv.running = false srv.lock.Unlock() - srvlog.Infoln("Stopping Server") + glog.V(logger.Info).Infoln("Stopping Server") srv.ntab.Close() if srv.listener != nil { // this unblocks listener Accept @@ -263,13 +263,13 @@ func (srv *Server) Stop() { // main loop for adding connections via listening func (srv *Server) listenLoop() { defer srv.loopWG.Done() - srvlog.Infoln("Listening on", srv.listener.Addr()) + glog.V(logger.Info).Infoln("Listening on", srv.listener.Addr()) for { conn, err := srv.listener.Accept() if err != nil { return } - srvlog.Debugf("Accepted conn %v\n", conn.RemoteAddr()) + glog.V(logger.Debug).Infof("Accepted conn %v\n", conn.RemoteAddr()) srv.peerWG.Add(1) go srv.startPeer(conn, nil) } @@ -328,10 +328,10 @@ func (srv *Server) dialLoop() { func (srv *Server) dialNode(dest *discover.Node) { addr := &net.TCPAddr{IP: dest.IP, Port: dest.TCPPort} - srvlog.Debugf("Dialing %v\n", dest) + glog.V(logger.Debug).Infof("Dialing %v\n", dest) conn, err := srv.Dialer.Dial("tcp", addr.String()) if err != nil { - srvlog.DebugDetailf("dial error: %v", err) + glog.V(logger.Detail).Infof("dial error: %v", err) return } srv.startPeer(conn, dest) @@ -365,7 +365,7 @@ func (srv *Server) startPeer(fd net.Conn, dest *discover.Node) { conn, err := srv.setupFunc(fd, srv.PrivateKey, srv.ourHandshake, dest) if err != nil { fd.Close() - srvlog.Debugf("Handshake with %v failed: %v", fd.RemoteAddr(), err) + glog.V(logger.Debug).Infof("Handshake with %v failed: %v", fd.RemoteAddr(), err) return } @@ -375,12 +375,12 @@ func (srv *Server) startPeer(fd net.Conn, dest *discover.Node) { } p := newPeer(fd, conn, srv.Protocols) if ok, reason := srv.addPeer(conn.ID, p); !ok { - srvlog.DebugDetailf("Not adding %v (%v)\n", p, reason) + glog.V(logger.Detail).Infof("Not adding %v (%v)\n", p, reason) p.politeDisconnect(reason) return } - srvlog.Debugf("Added %v\n", p) + glog.V(logger.Debug).Infof("Added %v\n", p) srvjslog.LogJson(&logger.P2PConnected{ RemoteId: fmt.Sprintf("%x", conn.ID[:]), RemoteAddress: fd.RemoteAddr().String(), @@ -394,7 +394,7 @@ func (srv *Server) startPeer(fd net.Conn, dest *discover.Node) { discreason := p.run() srv.removePeer(p) - srvlog.Debugf("Removed %v (%v)\n", p, discreason) + glog.V(logger.Debug).Infof("Removed %v (%v)\n", p, discreason) srvjslog.LogJson(&logger.P2PDisconnected{ RemoteId: fmt.Sprintf("%x", conn.ID[:]), NumConnections: srv.PeerCount(), diff --git a/whisper/whisper.go b/whisper/whisper.go index 709667729..00dcb1932 100644 --- a/whisper/whisper.go +++ b/whisper/whisper.go @@ -11,6 +11,7 @@ import ( "github.com/ethereum/go-ethereum/crypto/ecies" "github.com/ethereum/go-ethereum/event/filter" "github.com/ethereum/go-ethereum/logger" + "github.com/ethereum/go-ethereum/logger/glog" "github.com/ethereum/go-ethereum/p2p" "gopkg.in/fatih/set.v0" ) @@ -29,8 +30,6 @@ type MessageEvent struct { const DefaultTtl = 50 * time.Second -var wlogger = logger.NewLogger("SHH") - type Whisper struct { protocol p2p.Protocol filters *filter.Filters @@ -70,7 +69,7 @@ func (self *Whisper) Version() uint { } func (self *Whisper) Start() { - wlogger.Infoln("Whisper started") + glog.V(logger.Info).Infoln("Whisper started") go self.update() } @@ -195,7 +194,7 @@ func (self *Whisper) add(envelope *Envelope) error { go self.postEvent(envelope) } - wlogger.DebugDetailf("added whisper envelope %x\n", envelope) + glog.V(logger.Detail).Infof("added whisper envelope %x\n", envelope) return nil }