diff --git a/ethchain/block_chain.go b/ethchain/block_chain.go index 286a158ba2..d0fea6641d 100644 --- a/ethchain/block_chain.go +++ b/ethchain/block_chain.go @@ -2,13 +2,15 @@ package ethchain import ( "bytes" + "github.com/ethereum/eth-go/ethlog" "github.com/ethereum/eth-go/ethutil" "github.com/ethereum/eth-go/ethwire" - "log" "math" "math/big" ) +var chainlogger = ethlog.NewLogger("CHAIN") + type BlockChain struct { Ethereum EthManager // The famous, the fabulous Mister GENESIIIIIIS (block) @@ -129,38 +131,38 @@ func (bc *BlockChain) FindCanonicalChain(blocks []*Block, commonBlockHash []byte // Start with the newest block we got, all the way back to the common block we both know for _, block := range blocks { if bytes.Compare(block.Hash(), commonBlockHash) == 0 { - log.Println("[CHAIN] We have found the common parent block, breaking") + chainlogger.Infoln("[CHAIN] We have found the common parent block, breaking") break } chainDifficulty.Add(chainDifficulty, bc.CalculateBlockTD(block)) } - log.Println("[CHAIN] Incoming chain difficulty:", chainDifficulty) + chainlogger.Infoln("Incoming chain difficulty:", chainDifficulty) curChainDifficulty := new(big.Int) block := bc.CurrentBlock for i := 0; block != nil; block = bc.GetBlock(block.PrevHash) { i++ if bytes.Compare(block.Hash(), commonBlockHash) == 0 { - log.Println("[CHAIN] We have found the common parent block, breaking") + chainlogger.Infoln("We have found the common parent block, breaking") break } anOtherBlock := bc.GetBlock(block.PrevHash) if anOtherBlock == nil { // We do not want to count the genesis block for difficulty since that's not being sent - log.Println("[CHAIN] At genesis block, breaking") + chainlogger.Infoln("At genesis block, breaking") break } curChainDifficulty.Add(curChainDifficulty, bc.CalculateBlockTD(block)) } - log.Println("[CHAIN] Current chain difficulty:", curChainDifficulty) + chainlogger.Infoln("Current chain difficulty:", curChainDifficulty) if chainDifficulty.Cmp(curChainDifficulty) == 1 { - log.Printf("[CHAIN] The incoming Chain beat our asses, resetting to block: %x", commonBlockHash) + chainlogger.Infof("The incoming Chain beat our asses, resetting to block: %x", commonBlockHash) bc.ResetTillBlockHash(commonBlockHash) return false } else { - log.Println("[CHAIN] Our chain showed the incoming chain who is boss. Ignoring.") + chainlogger.Infoln("Our chain showed the incoming chain who is boss. Ignoring.") return true } } @@ -189,7 +191,7 @@ func (bc *BlockChain) ResetTillBlockHash(hash []byte) error { var block *Block for ; block != nil; block = bc.GetBlock(block.PrevHash) { if bytes.Compare(block.Hash(), hash) == 0 { - log.Println("[CHAIN] We have arrived at the the common parent block, breaking") + chainlogger.Infoln("We have arrived at the the common parent block, breaking") break } err = ethutil.Config.Db.Delete(block.Hash()) @@ -197,7 +199,7 @@ func (bc *BlockChain) ResetTillBlockHash(hash []byte) error { return err } } - log.Println("[CHAIN] Split chain deleted and reverted to common parent block.") + chainlogger.Infoln("Split chain deleted and reverted to common parent block.") return nil } @@ -226,7 +228,7 @@ func (bc *BlockChain) GetChainFromHash(hash []byte, max uint64) []interface{} { // Get the block of the chain block := bc.GetBlock(currentHash) if block == nil { - ethutil.Config.Log.Debugf("Unexpected error during GetChainFromHash: Unable to find %x\n", currentHash) + chainlogger.Debugf("Unexpected error during GetChainFromHash: Unable to find %x\n", currentHash) break } @@ -285,7 +287,7 @@ func (bc *BlockChain) setLastBlock() { bc.LastBlockHash = block.Hash() bc.LastBlockNumber = block.Number.Uint64() - ethutil.Config.Log.Infof("[CHAIN] Last known block height #%d\n", bc.LastBlockNumber) + chainlogger.Infof("Last known block height #%d\n", bc.LastBlockNumber) } else { AddTestNetFunds(bc.genesisBlock) @@ -293,14 +295,14 @@ func (bc *BlockChain) setLastBlock() { // Prepare the genesis block bc.Add(bc.genesisBlock) - //log.Printf("root %x\n", bm.bc.genesisBlock.State().Root) + //chainlogger.Infof("root %x\n", bm.bc.genesisBlock.State().Root) //bm.bc.genesisBlock.PrintHash() } // Set the last know difficulty (might be 0x0 as initial value, Genesis) bc.TD = ethutil.BigD(ethutil.Config.Db.LastKnownTD()) - ethutil.Config.Log.Infof("Last block: %x\n", bc.CurrentBlock.Hash()) + chainlogger.Infof("Last block: %x\n", bc.CurrentBlock.Hash()) } func (bc *BlockChain) SetTotalDifficulty(td *big.Int) { @@ -357,6 +359,6 @@ func (bc *BlockChain) writeBlockInfo(block *Block) { func (bc *BlockChain) Stop() { if bc.CurrentBlock != nil { - log.Println("[CHAIN] Stopped") + chainlogger.Infoln("Stopped") } } diff --git a/ethchain/dagger.go b/ethchain/dagger.go index 565e1e4473..08c4826dbf 100644 --- a/ethchain/dagger.go +++ b/ethchain/dagger.go @@ -1,15 +1,17 @@ package ethchain import ( + "github.com/ethereum/eth-go/ethlog" "github.com/ethereum/eth-go/ethutil" "github.com/obscuren/sha3" "hash" - "log" "math/big" "math/rand" "time" ) +var powlogger = ethlog.NewLogger("POW") + type PoW interface { Search(block *Block, reactChan chan ethutil.React) []byte Verify(hash []byte, diff *big.Int, nonce []byte) bool @@ -29,14 +31,13 @@ func (pow *EasyPow) Search(block *Block, reactChan chan ethutil.React) []byte { for { select { case <-reactChan: - //ethutil.Config.Log.Infoln("[POW] Received reactor event; breaking out.") return nil default: i++ if i%1234567 == 0 { elapsed := time.Now().UnixNano() - start hashes := ((float64(1e9) / float64(elapsed)) * float64(i)) / 1000 - ethutil.Config.Log.Infoln("[POW] Hashing @", int64(hashes), "khash") + powlogger.Infoln("Hashing @", int64(hashes), "khash") } sha := ethutil.Sha3Bin(big.NewInt(r.Int63()).Bytes()) @@ -81,7 +82,7 @@ func (dag *Dagger) Find(obj *big.Int, resChan chan int64) { rnd := r.Int63() res := dag.Eval(big.NewInt(rnd)) - log.Printf("rnd %v\nres %v\nobj %v\n", rnd, res, obj) + powlogger.Infof("rnd %v\nres %v\nobj %v\n", rnd, res, obj) if res.Cmp(obj) < 0 { // Post back result on the channel resChan <- rnd diff --git a/ethchain/state.go b/ethchain/state.go index a08dfac83e..e28b919099 100644 --- a/ethchain/state.go +++ b/ethchain/state.go @@ -125,7 +125,7 @@ func (self *State) GetOrNewStateObject(addr []byte) *StateObject { } func (self *State) NewStateObject(addr []byte) *StateObject { - ethutil.Config.Log.Printf(ethutil.LogLevelInfo, "(+) %x\n", addr) + statelogger.Infof("(+) %x\n", addr) stateObject := NewStateObject(addr) self.stateObjects[string(addr)] = stateObject diff --git a/ethchain/state_manager.go b/ethchain/state_manager.go index 7444d51808..312ba3084e 100644 --- a/ethchain/state_manager.go +++ b/ethchain/state_manager.go @@ -3,7 +3,7 @@ package ethchain import ( "bytes" "container/list" - "fmt" + "github.com/ethereum/eth-go/ethlog" "github.com/ethereum/eth-go/ethutil" "github.com/ethereum/eth-go/ethwire" "math/big" @@ -11,6 +11,8 @@ import ( "time" ) +var statelogger = ethlog.NewLogger("STATE") + type BlockProcessor interface { ProcessBlock(block *Block) } @@ -120,7 +122,7 @@ done: break done default: - ethutil.Config.Log.Infoln(err) + statelogger.Infoln(err) } } @@ -172,10 +174,10 @@ func (sm *StateManager) Process(block *Block, dontReact bool) (err error) { if err != nil { if len(receipts) == len(block.Receipts()) { for i, receipt := range block.Receipts() { - ethutil.Config.Log.Debugf("diff (r) %v ~ %x <=> (c) %v ~ %x (%x)\n", receipt.CumulativeGasUsed, receipt.PostState[0:4], receipts[i].CumulativeGasUsed, receipts[i].PostState[0:4], receipt.Tx.Hash()) + statelogger.Debugf("diff (r) %v ~ %x <=> (c) %v ~ %x (%x)\n", receipt.CumulativeGasUsed, receipt.PostState[0:4], receipts[i].CumulativeGasUsed, receipts[i].PostState[0:4], receipt.Tx.Hash()) } } else { - ethutil.Config.Log.Debugln("Unable to print receipt diff. Length didn't match", len(receipts), "for", len(block.Receipts())) + statelogger.Warnln("Unable to print receipt diff. Length didn't match", len(receipts), "for", len(block.Receipts())) } } }() @@ -186,19 +188,19 @@ func (sm *StateManager) Process(block *Block, dontReact bool) (err error) { // Block validation if err = sm.ValidateBlock(block); err != nil { - fmt.Println("[SM] Error validating block:", err) + statelogger.Errorln("Error validating block:", err) return err } // I'm not sure, but I don't know if there should be thrown // any errors at this time. if err = sm.AccumelateRewards(state, block); err != nil { - fmt.Println("[SM] Error accumulating reward", err) + statelogger.Errorln("Error accumulating reward", err) return err } if !block.State().Cmp(state) { - err = fmt.Errorf("Invalid merkle root.\nrec: %x\nis: %x", block.State().trie.Root, state.trie.Root) + statelogger.Errorf("Invalid merkle root.\nrec: %x\nis: %x", block.State().trie.Root, state.trie.Root) return } @@ -211,7 +213,7 @@ func (sm *StateManager) Process(block *Block, dontReact bool) (err error) { sm.bc.Add(block) sm.notifyChanges(state) - ethutil.Config.Log.Infof("[STATE] Added block #%d (%x)\n", block.Number, block.Hash()) + statelogger.Infof("Added block #%d (%x)\n", block.Number, block.Hash()) if dontReact == false { sm.Ethereum.Reactor().Post("newBlock", block) @@ -222,7 +224,7 @@ func (sm *StateManager) Process(block *Block, dontReact bool) (err error) { sm.Ethereum.TxPool().RemoveInvalid(state) } else { - fmt.Println("total diff failed") + statelogger.Errorln("total diff failed") } return nil diff --git a/ethchain/state_object.go b/ethchain/state_object.go index 270c9a7f8c..480b4055df 100644 --- a/ethchain/state_object.go +++ b/ethchain/state_object.go @@ -130,13 +130,13 @@ func (c *StateObject) ReturnGas(gas, price *big.Int, state *State) { func (c *StateObject) AddAmount(amount *big.Int) { c.SetAmount(new(big.Int).Add(c.Amount, amount)) - ethutil.Config.Log.Printf(ethutil.LogLevelInfo, "%x: #%d %v (+ %v)\n", c.Address(), c.Nonce, c.Amount, amount) + statelogger.Infof("%x: #%d %v (+ %v)\n", c.Address(), c.Nonce, c.Amount, amount) } func (c *StateObject) SubAmount(amount *big.Int) { c.SetAmount(new(big.Int).Sub(c.Amount, amount)) - ethutil.Config.Log.Printf(ethutil.LogLevelInfo, "%x: #%d %v (- %v)\n", c.Address(), c.Nonce, c.Amount, amount) + statelogger.Infof("%x: #%d %v (- %v)\n", c.Address(), c.Nonce, c.Amount, amount) } func (c *StateObject) SetAmount(amount *big.Int) { @@ -157,7 +157,7 @@ func (c *StateObject) ConvertGas(gas, price *big.Int) error { func (self *StateObject) SetGasPool(gasLimit *big.Int) { self.gasPool = new(big.Int).Set(gasLimit) - ethutil.Config.Log.Printf(ethutil.LogLevelSystem, "%x: fuel (+ %v)", self.Address(), self.gasPool) + statelogger.DebugDetailf("%x: fuel (+ %v)", self.Address(), self.gasPool) } func (self *StateObject) BuyGas(gas, price *big.Int) error { diff --git a/ethchain/state_transition.go b/ethchain/state_transition.go index 1f5b4f9592..f84c3486bb 100644 --- a/ethchain/state_transition.go +++ b/ethchain/state_transition.go @@ -2,7 +2,6 @@ package ethchain import ( "fmt" - "github.com/ethereum/eth-go/ethutil" "math/big" ) @@ -135,12 +134,12 @@ func (self *StateTransition) preCheck() (err error) { } func (self *StateTransition) TransitionState() (err error) { - ethutil.Config.Log.Printf(ethutil.LogLevelInfo, "(~) %x\n", self.tx.Hash()) + statelogger.Infof("(~) %x\n", self.tx.Hash()) /* defer func() { if r := recover(); r != nil { - ethutil.Config.Log.Infoln(r) + logger.Infoln(r) err = fmt.Errorf("state transition err %v", r) } }() @@ -231,7 +230,7 @@ func (self *StateTransition) transferValue(sender, receiver *StateObject) error // Add the amount to receivers account which should conclude this transaction receiver.AddAmount(self.value) - //ethutil.Config.Log.Debugf("%x => %x (%v)\n", sender.Address()[:4], receiver.Address()[:4], self.value) + //statelogger.Debugf("%x => %x (%v)\n", sender.Address()[:4], receiver.Address()[:4], self.value) //} return nil diff --git a/ethchain/transaction_pool.go b/ethchain/transaction_pool.go index 24836222a9..6ab8d83d9d 100644 --- a/ethchain/transaction_pool.go +++ b/ethchain/transaction_pool.go @@ -3,15 +3,15 @@ package ethchain import ( "bytes" "container/list" - "errors" "fmt" - "github.com/ethereum/eth-go/ethutil" + "github.com/ethereum/eth-go/ethlog" "github.com/ethereum/eth-go/ethwire" - "log" "math/big" "sync" ) +var txplogger = ethlog.NewLogger("TXP") + const ( txPoolQueueSize = 50 ) @@ -97,7 +97,7 @@ func (pool *TxPool) ProcessTransaction(tx *Transaction, state *State, toContract fmt.Printf("state root before update %x\n", state.Root()) defer func() { if r := recover(); r != nil { - ethutil.Config.Log.Infoln(r) + txplogger.Infoln(r) err = fmt.Errorf("%v", r) } }() @@ -156,7 +156,7 @@ func (pool *TxPool) ProcessTransaction(tx *Transaction, state *State, toContract fmt.Printf("state root after receiver update %x\n", state.Root()) } - ethutil.Config.Log.Infof("[TXPL] Processed Tx %x\n", tx.Hash()) + txplogger.Infof("[TXPL] Processed Tx %x\n", tx.Hash()) return } @@ -168,7 +168,7 @@ func (pool *TxPool) ValidateTransaction(tx *Transaction) error { block := pool.Ethereum.BlockChain().CurrentBlock // Something has gone horribly wrong if this happens if block == nil { - return errors.New("[TXPL] No last block on the block chain") + return fmt.Errorf("[TXPL] No last block on the block chain") } if len(tx.Recipient) != 20 { @@ -188,7 +188,7 @@ func (pool *TxPool) ValidateTransaction(tx *Transaction) error { if tx.IsContract() { if tx.GasPrice.Cmp(big.NewInt(minGasPrice)) < 0 { - return fmt.Errorf("[TXPL] Gasprice to low, %s given should be at least %d.", tx.GasPrice, minGasPrice) + return fmt.Errorf("[TXPL] Gasprice too low, %s given should be at least %d.", tx.GasPrice, minGasPrice) } } @@ -215,12 +215,12 @@ out: // Validate the transaction err := pool.ValidateTransaction(tx) if err != nil { - ethutil.Config.Log.Debugln("Validating Tx failed", err) + txplogger.Debugln("Validating Tx failed", err) } else { // Call blocking version. pool.addTransaction(tx) - ethutil.Config.Log.Debugf("(t) %x => %x (%v) %x\n", tx.Sender()[:4], tx.Recipient[:4], tx.Value, tx.Hash()) + txplogger.Debugf("(t) %x => %x (%v) %x\n", tx.Sender()[:4], tx.Recipient[:4], tx.Value, tx.Hash()) // Notify the subscribers pool.Ethereum.Reactor().Post("newTx:pre", tx) @@ -282,5 +282,5 @@ func (pool *TxPool) Stop() { pool.Flush() - log.Println("[TXP] Stopped") + txplogger.Infoln("Stopped") } diff --git a/ethchain/vm.go b/ethchain/vm.go index 199eaae50c..82591e2745 100644 --- a/ethchain/vm.go +++ b/ethchain/vm.go @@ -2,11 +2,14 @@ package ethchain import ( "fmt" + "github.com/ethereum/eth-go/ethlog" "github.com/ethereum/eth-go/ethutil" "math" "math/big" ) +var vmlogger = ethlog.NewLogger("VM") + var ( GasStep = big.NewInt(1) GasSha = big.NewInt(20) @@ -72,7 +75,7 @@ func (self *Vm) Printf(format string, v ...interface{}) *Vm { func (self *Vm) Endl() *Vm { if self.Verbose { - ethutil.Config.Log.Infoln(self.logStr) + vmlogger.Infoln(self.logStr) self.logStr = "" } @@ -93,11 +96,11 @@ func (vm *Vm) RunClosure(closure *Closure, hook DebugHook) (ret []byte, err erro if r := recover(); r != nil { ret = closure.Return(nil) err = fmt.Errorf("%v", r) - fmt.Println(err) + vmlogger.Errorln("vm err", err) } }() - ethutil.Config.Log.Debugf("[VM] (~) %x gas: %v (d) %x\n", closure.object.Address(), closure.Gas, closure.Args) + vmlogger.Debugf("(~) %x gas: %v (d) %x\n", closure.object.Address(), closure.Gas, closure.Args) var ( op OpCode @@ -642,7 +645,7 @@ func (vm *Vm) RunClosure(closure *Closure, hook DebugHook) (ret []byte, err erro args := mem.Get(inOffset.Int64(), inSize.Int64()) if closure.object.Amount.Cmp(value) < 0 { - ethutil.Config.Log.Debugf("Insufficient funds to transfer value. Req %v, has %v", value, closure.object.Amount) + vmlogger.Debugf("Insufficient funds to transfer value. Req %v, has %v", value, closure.object.Amount) stack.Push(ethutil.BigFalse) } else { @@ -661,7 +664,7 @@ func (vm *Vm) RunClosure(closure *Closure, hook DebugHook) (ret []byte, err erro if err != nil { stack.Push(ethutil.BigFalse) - ethutil.Config.Log.Debugf("Closure execution failed. %v\n", err) + vmlogger.Debugf("Closure execution failed. %v\n", err) vm.err = err vm.state.Set(snapshot) @@ -696,7 +699,7 @@ func (vm *Vm) RunClosure(closure *Closure, hook DebugHook) (ret []byte, err erro return closure.Return(nil), nil default: - ethutil.Config.Log.Debugf("Invalid opcode %x\n", op) + vmlogger.Debugf("Invalid opcode %x\n", op) return closure.Return(nil), fmt.Errorf("Invalid opcode %x", op) } diff --git a/ethereum.go b/ethereum.go index 6345f8864d..a3df23e924 100644 --- a/ethereum.go +++ b/ethereum.go @@ -5,11 +5,11 @@ import ( "fmt" "github.com/ethereum/eth-go/ethchain" "github.com/ethereum/eth-go/ethdb" + "github.com/ethereum/eth-go/ethlog" "github.com/ethereum/eth-go/ethrpc" "github.com/ethereum/eth-go/ethutil" "github.com/ethereum/eth-go/ethwire" "io/ioutil" - "log" "math/rand" "net" "net/http" @@ -20,6 +20,8 @@ import ( "time" ) +var ethlogger = ethlog.NewLogger("SERV") + func eachPeer(peers *list.List, callback func(*Peer, *list.Element)) { // Loop thru the peers and close them (if we had them) for e := peers.Front(); e != nil; e = e.Next() { @@ -85,7 +87,7 @@ func New(caps Caps, usePnp bool) (*Ethereum, error) { if usePnp { nat, err = Discover() if err != nil { - ethutil.Config.Log.Debugln("UPnP failed", err) + ethlogger.Debugln("UPnP failed", err) } } @@ -163,7 +165,7 @@ func (s *Ethereum) AddPeer(conn net.Conn) { if s.peers.Len() < s.MaxPeers { peer.Start() } else { - ethutil.Config.Log.Debugf("[SERV] Max connected peers reached. Not adding incoming peer.") + ethlogger.Debugf("Max connected peers reached. Not adding incoming peer.") } } } @@ -223,7 +225,7 @@ func (s *Ethereum) ConnectToPeer(addr string) error { if phost == chost { alreadyConnected = true - //ethutil.Config.Log.Debugf("[SERV] Peer %s already added.\n", chost) + //ethlogger.Debugf("Peer %s already added.\n", chost) return } }) @@ -340,12 +342,12 @@ func (s *Ethereum) Start(seed bool) { // Bind to addr and port ln, err := net.Listen("tcp", ":"+s.Port) if err != nil { - ethutil.Config.Log.Infof("port=%s in use. Connection listening disabled.") + ethlogger.Warnf("Port %s in use. Connection listening disabled. Acting as client", s.Port) s.listening = false } else { s.listening = true // Starting accepting connections - ethutil.Config.Log.Infoln("Ready and accepting connections") + ethlogger.Infoln("Ready and accepting connections") // Start the peer handler go s.peerHandler(ln) } @@ -360,10 +362,11 @@ func (s *Ethereum) Start(seed bool) { if seed { s.Seed() } + ethlogger.Infoln("Server started") } func (s *Ethereum) Seed() { - ethutil.Config.Log.Debugln("[SERV] Retrieving seed nodes") + ethlogger.Debugln("Retrieving seed nodes") // Eth-Go Bootstrapping ips, er := net.LookupIP("seed.bysh.me") @@ -371,7 +374,7 @@ func (s *Ethereum) Seed() { peers := []string{} for _, ip := range ips { node := fmt.Sprintf("%s:%d", ip.String(), 30303) - ethutil.Config.Log.Debugln("[SERV] Found DNS Go Peer:", node) + ethlogger.Debugln("Found DNS Go Peer:", node) peers = append(peers, node) } s.ProcessPeerList(peers) @@ -391,11 +394,11 @@ func (s *Ethereum) Seed() { for _, a := range addr { // Build string out of SRV port and Resolved IP peer := net.JoinHostPort(a, port) - ethutil.Config.Log.Debugln("[SERV] Found DNS Bootstrap Peer:", peer) + ethlogger.Debugln("Found DNS Bootstrap Peer:", peer) peers = append(peers, peer) } } else { - ethutil.Config.Log.Debugln("[SERV] Couldn't resolve :", target) + ethlogger.Debugln("Couldn't resolve :", target) } } // Connect to Peer list @@ -404,13 +407,13 @@ func (s *Ethereum) Seed() { // Fallback to servers.poc3.txt resp, err := http.Get("http://www.ethereum.org/servers.poc3.txt") if err != nil { - log.Println("Fetching seed failed:", err) + ethlogger.Warnln("Fetching seed failed:", err) return } defer resp.Body.Close() body, err := ioutil.ReadAll(resp.Body) if err != nil { - log.Println("Reading seed failed:", err) + ethlogger.Warnln("Reading seed failed:", err) return } @@ -422,7 +425,7 @@ func (s *Ethereum) peerHandler(listener net.Listener) { for { conn, err := listener.Accept() if err != nil { - ethutil.Config.Log.Debugln(err) + ethlogger.Debugln(err) continue } @@ -447,6 +450,7 @@ func (s *Ethereum) Stop() { s.txPool.Stop() s.stateManager.Stop() + ethlogger.Infoln("Server stopped") close(s.shutdownChan) } @@ -468,13 +472,13 @@ out: var err error _, err = s.nat.AddPortMapping("TCP", int(lport), int(lport), "eth listen port", 20*60) if err != nil { - ethutil.Config.Log.Debugln("can't add UPnP port mapping:", err) + ethlogger.Debugln("can't add UPnP port mapping:", err) break out } if first && err == nil { _, err = s.nat.GetExternalAddress() if err != nil { - ethutil.Config.Log.Debugln("UPnP can't get external address:", err) + ethlogger.Debugln("UPnP can't get external address:", err) continue out } first = false @@ -488,8 +492,8 @@ out: timer.Stop() if err := s.nat.DeletePortMapping("TCP", int(lport), int(lport)); err != nil { - ethutil.Config.Log.Debugln("unable to remove UPnP port mapping:", err) + ethlogger.Debugln("unable to remove UPnP port mapping:", err) } else { - ethutil.Config.Log.Debugln("succesfully disestablished UPnP port mapping") + ethlogger.Debugln("succesfully disestablished UPnP port mapping") } } diff --git a/ethlog/README.md b/ethlog/README.md new file mode 100644 index 0000000000..d9b69e1066 --- /dev/null +++ b/ethlog/README.md @@ -0,0 +1,62 @@ +## Features + +- packages use tagged logger sending log messages to shared (process-wide) logging engine +- log writers (interface ethlog.LogSystem) can be added to the logging engine by wrappers/guis/clients +- shared logging engine dispatching to multiple log systems +- log level can be set separately per log system +- async logging thread: logging IO does not block main thread +- log messages are synchronously stringified to avoid incorrectly logging of changed states +- log level enum: ethlog.LogLevel: Silence, ErrorLevel, WarnLevel, InfoLevel, DebugLevel, DebugDetailLevel + +## Usage + +In an ethereum component package: + + import "github.com/ethereum/eth-go/ethlog" + + // package-wide logger using tag + var logger = ethlog.NewLogger("TAG") + +Logger provides named Printf and Println style methods for all loglevels + + logger.Infoln("this is info") # > [TAG] This is info + logger.Infof("this %v is info", object) # > [TAG] This object is info + +Ethereum wrappers should register log systems conforming to ethlog.LogSystem + + import "github.com/ethereum/eth-go/ethlog" + + type CustomLogWriter struct { + logLevel ethlog.LogLevel + } + + func (t *TestLogSystem) SetLogLevel(i LogLevel) { + t.level = i + } + + func (t *TestLogSystem) GetLogLevel() LogLevel { + return t.level + } + + func (c *CustomLogWriter) Printf(format string, v...interface{}) { + //.... + } + + func (c *CustomLogWriter) Println(v...interface{}) { + //.... + } + + ethlog.AddLogWriter(&CustomLogWriter{}) + +ethlog also provides constructors for that wrap io.Writers into a standard logger with a settable level: + + filename := "test.log" + file, _ := os.OpenFile(filename, os.O_RDWR|os.O_CREATE, os.ModePerm) + fileLogSystem := NewStdLogSystem(file, 0, WarnLevel) + AddLogSystem(fileLogSystem) + stdOutLogSystem := NewStdLogSystem(os.Stdout, 0, WarnLevel) + AddLogSystem(stdOutLogSystem) + + + + diff --git a/ethlog/loggers.go b/ethlog/loggers.go new file mode 100644 index 0000000000..9ebe590967 --- /dev/null +++ b/ethlog/loggers.go @@ -0,0 +1,188 @@ +package ethlog + +import ( + "fmt" + "io" + "log" + "os" + "sync" +) + +type LogSystem interface { + GetLogLevel() LogLevel + SetLogLevel(i LogLevel) + Println(v ...interface{}) + Printf(format string, v ...interface{}) +} + +type logMessage struct { + LogLevel LogLevel + format bool + msg string +} + +func newPrintlnLogMessage(level LogLevel, tag string, v ...interface{}) *logMessage { + return &logMessage{level, false, fmt.Sprintf("[%s] %s", tag, fmt.Sprint(v...))} +} + +func newPrintfLogMessage(level LogLevel, tag string, format string, v ...interface{}) *logMessage { + return &logMessage{level, true, fmt.Sprintf("[%s] %s", tag, fmt.Sprintf(format, v...))} +} + +func (msg *logMessage) send(logger LogSystem) { + if msg.format { + logger.Printf(msg.msg) + } else { + logger.Println(msg.msg) + } +} + +var logMessages chan (*logMessage) +var logSystems []LogSystem +var drained = true + +type LogLevel uint8 + +const ( + Silence LogLevel = iota + ErrorLevel + WarnLevel + InfoLevel + DebugLevel + DebugDetailLevel +) + +// log messages are dispatched to log writers +func start() { + for { + select { + case msg := <-logMessages: + for _, logSystem := range logSystems { + if logSystem.GetLogLevel() >= msg.LogLevel { + msg.send(logSystem) + } + } + default: + drained = true + } + } +} + +// waits until log messages are drained (dispatched to log writers) +func Flush() { + for !drained { + } +} + +type Logger struct { + tag string +} + +func NewLogger(tag string) *Logger { + return &Logger{tag} +} + +func AddLogSystem(logSystem LogSystem) { + var mutex = &sync.Mutex{} + mutex.Lock() + defer mutex.Unlock() + if logSystems == nil { + logMessages = make(chan *logMessage) + go start() + } + logSystems = append(logSystems, logSystem) +} + +func (logger *Logger) sendln(level LogLevel, v ...interface{}) { + if logMessages != nil { + msg := newPrintlnLogMessage(level, logger.tag, v...) + drained = false + logMessages <- msg + } +} + +func (logger *Logger) sendf(level LogLevel, format string, v ...interface{}) { + if logMessages != nil { + msg := newPrintfLogMessage(level, logger.tag, format, v...) + drained = false + logMessages <- msg + } +} + +func (logger *Logger) Errorln(v ...interface{}) { + logger.sendln(ErrorLevel, v...) +} + +func (logger *Logger) Warnln(v ...interface{}) { + logger.sendln(WarnLevel, v...) +} + +func (logger *Logger) Infoln(v ...interface{}) { + logger.sendln(InfoLevel, v...) +} + +func (logger *Logger) Debugln(v ...interface{}) { + logger.sendln(DebugLevel, v...) +} + +func (logger *Logger) DebugDetailln(v ...interface{}) { + logger.sendln(DebugDetailLevel, v...) +} + +func (logger *Logger) Errorf(format string, v ...interface{}) { + logger.sendf(ErrorLevel, format, v...) +} + +func (logger *Logger) Warnf(format string, v ...interface{}) { + logger.sendf(WarnLevel, format, v...) +} + +func (logger *Logger) Infof(format string, v ...interface{}) { + logger.sendf(InfoLevel, format, v...) +} + +func (logger *Logger) Debugf(format string, v ...interface{}) { + logger.sendf(DebugLevel, format, v...) +} + +func (logger *Logger) DebugDetailf(format string, v ...interface{}) { + logger.sendf(DebugDetailLevel, format, v...) +} + +func (logger *Logger) Fatalln(v ...interface{}) { + logger.sendln(ErrorLevel, v...) + Flush() + os.Exit(0) +} + +func (logger *Logger) Fatalf(format string, v ...interface{}) { + logger.sendf(ErrorLevel, format, v...) + Flush() + os.Exit(0) +} + +type StdLogSystem struct { + logger *log.Logger + level LogLevel +} + +func (t *StdLogSystem) Println(v ...interface{}) { + t.logger.Println(v...) +} + +func (t *StdLogSystem) Printf(format string, v ...interface{}) { + t.logger.Printf(format, v...) +} + +func (t *StdLogSystem) SetLogLevel(i LogLevel) { + t.level = i +} + +func (t *StdLogSystem) GetLogLevel() LogLevel { + return t.level +} + +func NewStdLogSystem(writer io.Writer, flags int, level LogLevel) *StdLogSystem { + logger := log.New(writer, "", flags) + return &StdLogSystem{logger, level} +} diff --git a/ethlog/loggers_test.go b/ethlog/loggers_test.go new file mode 100644 index 0000000000..89f4166810 --- /dev/null +++ b/ethlog/loggers_test.go @@ -0,0 +1,109 @@ +package ethlog + +import ( + "fmt" + "io/ioutil" + "os" + "testing" +) + +type TestLogSystem struct { + Output string + level LogLevel +} + +func (t *TestLogSystem) Println(v ...interface{}) { + t.Output += fmt.Sprintln(v...) +} + +func (t *TestLogSystem) Printf(format string, v ...interface{}) { + t.Output += fmt.Sprintf(format, v...) +} + +func (t *TestLogSystem) SetLogLevel(i LogLevel) { + t.level = i +} + +func (t *TestLogSystem) GetLogLevel() LogLevel { + return t.level +} + +func quote(s string) string { + return fmt.Sprintf("'%s'", s) +} + +func TestLoggerPrintln(t *testing.T) { + logger := NewLogger("TEST") + testLogSystem := &TestLogSystem{level: WarnLevel} + AddLogSystem(testLogSystem) + logger.Errorln("error") + logger.Warnln("warn") + logger.Infoln("info") + logger.Debugln("debug") + Flush() + output := testLogSystem.Output + fmt.Println(quote(output)) + if output != "[TEST] error\n[TEST] warn\n" { + t.Error("Expected logger output '[TEST] error\\n[TEST] warn\\n', got ", quote(testLogSystem.Output)) + } +} + +func TestLoggerPrintf(t *testing.T) { + logger := NewLogger("TEST") + testLogSystem := &TestLogSystem{level: WarnLevel} + AddLogSystem(testLogSystem) + logger.Errorf("error to %v\n", *testLogSystem) + logger.Warnf("warn") + logger.Infof("info") + logger.Debugf("debug") + Flush() + output := testLogSystem.Output + fmt.Println(quote(output)) + if output != "[TEST] error to { 2}\n[TEST] warn" { + t.Error("Expected logger output '[TEST] error to { 2}\\n[TEST] warn', got ", quote(testLogSystem.Output)) + } +} + +func TestMultipleLogSystems(t *testing.T) { + logger := NewLogger("TEST") + testLogSystem0 := &TestLogSystem{level: ErrorLevel} + testLogSystem1 := &TestLogSystem{level: WarnLevel} + AddLogSystem(testLogSystem0) + AddLogSystem(testLogSystem1) + logger.Errorln("error") + logger.Warnln("warn") + Flush() + output0 := testLogSystem0.Output + output1 := testLogSystem1.Output + if output0 != "[TEST] error\n" { + t.Error("Expected logger 0 output '[TEST] error\\n', got ", quote(testLogSystem0.Output)) + } + if output1 != "[TEST] error\n[TEST] warn\n" { + t.Error("Expected logger 1 output '[TEST] error\\n[TEST] warn\\n', got ", quote(testLogSystem1.Output)) + } +} + +func TestFileLogSystem(t *testing.T) { + logger := NewLogger("TEST") + filename := "test.log" + file, _ := os.OpenFile(filename, os.O_RDWR|os.O_CREATE, os.ModePerm) + testLogSystem := NewStdLogSystem(file, 0, WarnLevel) + AddLogSystem(testLogSystem) + logger.Errorf("error to %s\n", filename) + logger.Warnln("warn") + Flush() + contents, _ := ioutil.ReadFile(filename) + output := string(contents) + fmt.Println(quote(output)) + if output != "[TEST] error to test.log\n[TEST] warn\n" { + t.Error("Expected contents of file 'test.log': '[TEST] error to test.log\\n[TEST] warn\\n', got ", quote(output)) + } else { + os.Remove(filename) + } +} + +func TestNoLogSystem(t *testing.T) { + logger := NewLogger("TEST") + logger.Warnln("warn") + Flush() +} diff --git a/ethminer/miner.go b/ethminer/miner.go index 4343b43336..66388723ec 100644 --- a/ethminer/miner.go +++ b/ethminer/miner.go @@ -3,11 +3,14 @@ package ethminer import ( "bytes" "github.com/ethereum/eth-go/ethchain" + "github.com/ethereum/eth-go/ethlog" "github.com/ethereum/eth-go/ethutil" "github.com/ethereum/eth-go/ethwire" "sort" ) +var logger = ethlog.NewLogger("MINER") + type Miner struct { pow ethchain.PoW ethereum ethchain.EthManager @@ -54,23 +57,28 @@ func NewDefaultMiner(coinbase []byte, ethereum ethchain.EthManager) Miner { return miner } + func (miner *Miner) Start() { // Prepare inital block //miner.ethereum.StateManager().Prepare(miner.block.State(), miner.block.State()) go miner.listener() + logger.Infoln("Started") } + func (miner *Miner) listener() { out: for { select { case <-miner.quitChan: + logger.Infoln("Stopped") break out case chanMessage := <-miner.reactChan: + if block, ok := chanMessage.Resource.(*ethchain.Block); ok { - //ethutil.Config.Log.Infoln("[MINER] Got new block via Reactor") + //logger.Infoln("Got new block via Reactor") if bytes.Compare(miner.ethereum.BlockChain().CurrentBlock.Hash(), block.Hash()) == 0 { // TODO: Perhaps continue mining to get some uncle rewards - //ethutil.Config.Log.Infoln("[MINER] New top block found resetting state") + //logger.Infoln("New top block found resetting state") // Filter out which Transactions we have that were not in this block var newtxs []*ethchain.Transaction @@ -92,7 +100,7 @@ out: } else { if bytes.Compare(block.PrevHash, miner.ethereum.BlockChain().CurrentBlock.PrevHash) == 0 { - ethutil.Config.Log.Infoln("[MINER] Adding uncle block") + logger.Infoln("Adding uncle block") miner.uncles = append(miner.uncles, block) } } @@ -120,8 +128,9 @@ out: } func (self *Miner) Stop() { - self.powQuitChan <- ethutil.React{} + logger.Infoln("Stopping...") self.quitChan <- true + self.powQuitChan <- ethutil.React{} } func (self *Miner) mineNewBlock() { @@ -137,14 +146,14 @@ func (self *Miner) mineNewBlock() { // Sort the transactions by nonce in case of odd network propagation sort.Sort(ethchain.TxByNonce{self.txs}) - // Accumulate all valid transaction and apply them to the new state + // Accumulate all valid transactions and apply them to the new state // Error may be ignored. It's not important during mining parent := self.ethereum.BlockChain().GetBlock(self.block.PrevHash) coinbase := self.block.State().GetOrNewStateObject(self.block.Coinbase) coinbase.SetGasPool(self.block.CalcGasLimit(parent)) receipts, txs, unhandledTxs, err := stateManager.ProcessTransactions(coinbase, self.block.State(), self.block, self.block, self.txs) if err != nil { - ethutil.Config.Log.Debugln("[MINER]", err) + logger.Debugln(err) } self.txs = append(txs, unhandledTxs...) @@ -156,18 +165,18 @@ func (self *Miner) mineNewBlock() { self.block.State().Update() - ethutil.Config.Log.Infoln("[MINER] Mining on block. Includes", len(self.txs), "transactions") + logger.Infof("Mining on block. Includes %v transactions", len(self.txs)) // Find a valid nonce self.block.Nonce = self.pow.Search(self.block, self.powQuitChan) if self.block.Nonce != nil { err := self.ethereum.StateManager().Process(self.block, false) if err != nil { - ethutil.Config.Log.Infoln(err) + logger.Infoln(err) } else { self.ethereum.Broadcast(ethwire.MsgBlockTy, []interface{}{self.block.Value().Val}) - ethutil.Config.Log.Infof("[MINER] 🔨 Mined block %x\n", self.block.Hash()) - ethutil.Config.Log.Infoln(self.block) + logger.Infof("🔨 Mined block %x\n", self.block.Hash()) + logger.Infoln(self.block) // Gather the new batch of transactions currently in the tx pool self.txs = self.ethereum.TxPool().CurrentTransactions() } diff --git a/ethpub/pub.go b/ethpub/pub.go index 05acdb0583..1bc9e0ce7d 100644 --- a/ethpub/pub.go +++ b/ethpub/pub.go @@ -5,12 +5,15 @@ import ( "encoding/hex" "encoding/json" "github.com/ethereum/eth-go/ethchain" + "github.com/ethereum/eth-go/ethlog" "github.com/ethereum/eth-go/ethutil" "math/big" "strings" "sync/atomic" ) +var logger = ethlog.NewLogger("PUB") + type PEthereum struct { manager ethchain.EthManager stateManager *ethchain.StateManager @@ -222,7 +225,7 @@ func (lib *PEthereum) createTx(key, recipient, valueStr, gasStr, gasPriceStr, sc lib.txPool.QueueTransaction(tx) if contractCreation { - ethutil.Config.Log.Infof("Contract addr %x", tx.CreationAddress()) + logger.Infof("Contract addr %x", tx.CreationAddress()) } return NewPReciept(contractCreation, tx.CreationAddress(), tx.Hash(), keyPair.Address()), nil diff --git a/ethrpc/packages.go b/ethrpc/packages.go index 3f57f69826..7102757803 100644 --- a/ethrpc/packages.go +++ b/ethrpc/packages.go @@ -184,7 +184,7 @@ func (p *EthereumApi) GetStorageAt(args *GetStorageArgs, reply *string) error { i, _ := new(big.Int).SetString(args.Key, 10) hx = ethutil.Hex(i.Bytes()) } - ethutil.Config.Log.Debugf("[JSON] GetStorageAt(%s, %s)\n", args.Address, hx) + logger.Debugf("GetStorageAt(%s, %s)\n", args.Address, hx) value := state.GetStorage(hx) *reply = NewSuccessRes(GetStorageAtRes{Address: args.Address, Key: args.Key, Value: value}) return nil diff --git a/ethrpc/server.go b/ethrpc/server.go index 3960e641c3..d9d6f695b5 100644 --- a/ethrpc/server.go +++ b/ethrpc/server.go @@ -2,13 +2,15 @@ package ethrpc import ( "fmt" + "github.com/ethereum/eth-go/ethlog" "github.com/ethereum/eth-go/ethpub" - "github.com/ethereum/eth-go/ethutil" "net" "net/rpc" "net/rpc/jsonrpc" ) +var logger = ethlog.NewLogger("JSON") + type JsonRpcServer struct { quit chan bool listener net.Listener @@ -25,7 +27,7 @@ out: } } - ethutil.Config.Log.Infoln("[JSON] Shutdown JSON-RPC server") + logger.Infoln("Shutdown JSON-RPC server") } func (s *JsonRpcServer) Stop() { @@ -33,7 +35,7 @@ func (s *JsonRpcServer) Stop() { } func (s *JsonRpcServer) Start() { - ethutil.Config.Log.Infoln("[JSON] Starting JSON-RPC server") + logger.Infoln("Starting JSON-RPC server") go s.exitHandler() rpc.Register(&EthereumApi{ethp: s.ethp}) rpc.HandleHTTP() @@ -41,10 +43,10 @@ func (s *JsonRpcServer) Start() { for { conn, err := s.listener.Accept() if err != nil { - ethutil.Config.Log.Infoln("[JSON] Error starting JSON-RPC:", err) + logger.Infoln("Error starting JSON-RPC:", err) break } - ethutil.Config.Log.Debugln("[JSON] Incoming request.") + logger.Debugln("Incoming request.") go jsonrpc.ServeConn(conn) } } diff --git a/ethutil/config.go b/ethutil/config.go index a573e108bc..aa4ae9c3eb 100644 --- a/ethutil/config.go +++ b/ethutil/config.go @@ -4,10 +4,7 @@ import ( "flag" "fmt" "github.com/rakyll/globalconf" - "log" "os" - "os/user" - "path" "runtime" ) @@ -15,7 +12,6 @@ import ( type config struct { Db Database - Log *Logger ExecPath string Debug bool Ver string @@ -26,62 +22,31 @@ type config struct { conf *globalconf.GlobalConf } -const defaultConf = ` -id = "" -port = 30303 -upnp = true -maxpeer = 10 -rpc = false -rpcport = 8080 -` - var Config *config -func ApplicationFolder(base string) string { - usr, _ := user.Current() - p := path.Join(usr.HomeDir, base) - - if len(base) > 0 { - //Check if the logging directory already exists, create it if not - _, err := os.Stat(p) - if err != nil { - if os.IsNotExist(err) { - log.Printf("Debug logging directory %s doesn't exist, creating it\n", p) - os.Mkdir(p, 0777) - - } - } - - iniFilePath := path.Join(p, "conf.ini") - _, err = os.Stat(iniFilePath) - if err != nil && os.IsNotExist(err) { - file, err := os.Create(iniFilePath) - if err != nil { - fmt.Println(err) - } else { - assetPath := path.Join(os.Getenv("GOPATH"), "src", "github.com", "ethereum", "go-ethereum", "ethereal", "assets") - file.Write([]byte(defaultConf + "\nasset_path = " + assetPath)) - } - } - } - - return p -} - // Read config // -// Initialize the global Config variable with default settings -func ReadConfig(base string, logTypes LoggerType, g *globalconf.GlobalConf, id string) *config { +// Initialize Config from Config File +func ReadConfig(ConfigFile string, Datadir string, Identifier string, EnvPrefix string) *config { if Config == nil { - path := ApplicationFolder(base) - - Config = &config{ExecPath: path, Debug: true, Ver: "0.5.14"} - Config.conf = g - Config.Identifier = id - Config.Log = NewLogger(logTypes, LogLevelDebug) + // create ConfigFile if does not exist, otherwise globalconf panic when trying to persist flags + _, err := os.Stat(ConfigFile) + if err != nil && os.IsNotExist(err) { + fmt.Printf("config file '%s' doesn't exist, creating it\n", ConfigFile) + os.Create(ConfigFile) + } + g, err := globalconf.NewWithOptions(&globalconf.Options{ + Filename: ConfigFile, + EnvPrefix: EnvPrefix, + }) + if err != nil { + fmt.Println(err) + } else { + g.ParseAll() + } + Config = &config{ExecPath: Datadir, Debug: true, Ver: "0.5.14", conf: g, Identifier: Identifier} Config.SetClientString("Ethereum(G)") } - return Config } @@ -98,137 +63,12 @@ func (c *config) SetIdentifier(id string) { c.Set("id", id) } +// provides persistence for flags func (c *config) Set(key, value string) { f := &flag.Flag{Name: key, Value: &confValue{value}} c.conf.Set("", f) } -type LoggerType byte - -const ( - LogFile = 0x1 - LogStd = 0x2 -) - -type LogSystem interface { - Println(v ...interface{}) - Printf(format string, v ...interface{}) -} - -type Logger struct { - logSys []LogSystem - logLevel int -} - -func NewLogger(flag LoggerType, level int) *Logger { - var loggers []LogSystem - - flags := log.LstdFlags - - if flag&LogFile > 0 { - file, err := os.OpenFile(path.Join(Config.ExecPath, "debug.log"), os.O_RDWR|os.O_CREATE|os.O_APPEND, os.ModePerm) - if err != nil { - log.Panic("unable to create file logger", err) - } - - log := log.New(file, "", flags) - - loggers = append(loggers, log) - } - if flag&LogStd > 0 { - log := log.New(os.Stdout, "", flags) - loggers = append(loggers, log) - } - - return &Logger{logSys: loggers, logLevel: level} -} - -func (self *Logger) SetLevel(level int) { - self.logLevel = level -} - -func (log *Logger) AddLogSystem(logger LogSystem) { - log.logSys = append(log.logSys, logger) -} - -const ( - LogLevelSystem = iota - LogLevelDebug - LogLevelInfo -) - -func (log *Logger) Debugln(v ...interface{}) { - if log.logLevel != LogLevelDebug { - return - } - - for _, logger := range log.logSys { - logger.Println(v...) - } -} - -func (log *Logger) Debugf(format string, v ...interface{}) { - if log.logLevel != LogLevelDebug { - return - } - - for _, logger := range log.logSys { - logger.Printf(format, v...) - } -} - -func (log *Logger) Infoln(v ...interface{}) { - if log.logLevel > LogLevelInfo { - return - } - - for _, logger := range log.logSys { - logger.Println(v...) - } -} - -func (log *Logger) Infof(format string, v ...interface{}) { - if log.logLevel > LogLevelInfo { - return - } - - for _, logger := range log.logSys { - logger.Printf(format, v...) - } -} - -func (log *Logger) Fatal(v ...interface{}) { - if log.logLevel > LogLevelInfo { - return - } - - for _, logger := range log.logSys { - logger.Println(v...) - } - - os.Exit(1) -} - -func (log *Logger) Println(level int, v ...interface{}) { - if log.logLevel > level { - return - } - - for _, logger := range log.logSys { - logger.Println(v...) - } -} - -func (log *Logger) Printf(level int, format string, v ...interface{}) { - if log.logLevel > level { - return - } - - for _, logger := range log.logSys { - logger.Printf(format, v...) - } -} - type confValue struct { value string } diff --git a/ethutil/encoding_test.go b/ethutil/encoding_test.go index cbfbc0eafa..10e1995c02 100644 --- a/ethutil/encoding_test.go +++ b/ethutil/encoding_test.go @@ -64,4 +64,4 @@ func TestCompactDecode(t *testing.T) { if !CompareIntSlice(res, exp) { t.Error("even terminated compact decode. Expected", exp, "got", res) } -} \ No newline at end of file +} diff --git a/peer.go b/peer.go index ca41689408..e50fd43f93 100644 --- a/peer.go +++ b/peer.go @@ -5,6 +5,7 @@ import ( "container/list" "fmt" "github.com/ethereum/eth-go/ethchain" + "github.com/ethereum/eth-go/ethlog" "github.com/ethereum/eth-go/ethutil" "github.com/ethereum/eth-go/ethwire" "net" @@ -14,6 +15,8 @@ import ( "time" ) +var peerlogger = ethlog.NewLogger("PEER") + const ( // The size of the output buffer for writing messages outputBufferSize = 50 @@ -178,7 +181,7 @@ func NewOutboundPeer(addr string, ethereum *Ethereum, caps Caps) *Peer { conn, err := net.DialTimeout("tcp", addr, 10*time.Second) if err != nil { - ethutil.Config.Log.Debugln("Connection to peer failed", err) + peerlogger.Debugln("Connection to peer failed", err) p.Stop() return } @@ -247,11 +250,11 @@ func (p *Peer) writeMessage(msg *ethwire.Msg) { } } - ethutil.Config.Log.Println(ethutil.LogLevelSystem, "<=", msg.Type, msg.Data) + peerlogger.DebugDetailln("<=", msg.Type, msg.Data) err := ethwire.WriteMessage(p.conn, msg) if err != nil { - ethutil.Config.Log.Debugln("[PEER] Can't send message:", err) + peerlogger.Debugln(" Can't send message:", err) // Stop the client if there was an error writing to it p.Stop() return @@ -276,7 +279,7 @@ out: case <-pingTimer.C: timeSince := time.Since(time.Unix(p.lastPong, 0)) if !p.pingStartTime.IsZero() && p.lastPong != 0 && timeSince > (pingPongTimer+30*time.Second) { - ethutil.Config.Log.Infof("[PEER] Peer did not respond to latest pong fast enough, it took %s, disconnecting.\n", timeSince) + peerlogger.Infof("Peer did not respond to latest pong fast enough, it took %s, disconnecting.\n", timeSince) p.Stop() return } @@ -318,10 +321,10 @@ func (p *Peer) HandleInbound() { // Wait for a message from the peer msgs, err := ethwire.ReadMessages(p.conn) if err != nil { - ethutil.Config.Log.Debugln(err) + peerlogger.Debugln(err) } for _, msg := range msgs { - ethutil.Config.Log.Println(ethutil.LogLevelSystem, "=>", msg.Type, msg.Data) + peerlogger.DebugDetailln("=>", msg.Type, msg.Data) switch msg.Type { case ethwire.MsgHandshakeTy: @@ -333,7 +336,7 @@ func (p *Peer) HandleInbound() { } case ethwire.MsgDiscTy: p.Stop() - ethutil.Config.Log.Infoln("Disconnect peer:", DiscReason(msg.Data.Get(0).Uint())) + peerlogger.Infoln("Disconnect peer:", DiscReason(msg.Data.Get(0).Uint())) case ethwire.MsgPingTy: // Respond back with pong p.QueueMessage(ethwire.NewMessage(ethwire.MsgPongTy, "")) @@ -358,8 +361,7 @@ func (p *Peer) HandleInbound() { continue } p.lastRequestedBlock = lastBlock - - ethutil.Config.Log.Infof("[PEER] Last block: %x. Checking if we have it locally.\n", lastBlock.Hash()) + peerlogger.Infof("Last block: %x. Checking if we have it locally.\n", lastBlock.Hash()) for i := msg.Data.Len() - 1; i >= 0; i-- { block = ethchain.NewBlockFromRlpValue(msg.Data.Get(i)) // Do we have this block on our chain? If so we can continue @@ -380,7 +382,7 @@ func (p *Peer) HandleInbound() { // we just keep increasing the amount of blocks. p.blocksRequested = p.blocksRequested * 2 - ethutil.Config.Log.Infof("[PEER] No common ancestor found, requesting %d more blocks.\n", p.blocksRequested) + peerlogger.Infof("No common ancestor found, requesting %d more blocks.\n", p.blocksRequested) p.catchingUp = false p.FindCommonParentBlock() break @@ -396,9 +398,9 @@ func (p *Peer) HandleInbound() { if err != nil { if ethutil.Config.Debug { - ethutil.Config.Log.Infof("[PEER] Block %x failed\n", block.Hash()) - ethutil.Config.Log.Infof("[PEER] %v\n", err) - ethutil.Config.Log.Debugln(block) + peerlogger.Infof("Block %x failed\n", block.Hash()) + peerlogger.Infof("%v\n", err) + peerlogger.Debugln(block) } break } else { @@ -415,7 +417,7 @@ func (p *Peer) HandleInbound() { if err != nil { // If the parent is unknown try to catch up with this peer if ethchain.IsParentErr(err) { - ethutil.Config.Log.Infoln("Attempting to catch. Parent known") + peerlogger.Infoln("Attempting to catch. Parent known") p.catchingUp = false p.CatchupWithPeer(p.ethereum.BlockChain().CurrentBlock.Hash()) } else if ethchain.IsValidationErr(err) { @@ -427,7 +429,7 @@ func (p *Peer) HandleInbound() { if p.catchingUp && msg.Data.Len() > 1 { if lastBlock != nil { blockInfo := lastBlock.BlockInfo() - ethutil.Config.Log.Printf(ethutil.LogLevelSystem, "Synced chain to #%d %x %x\n", blockInfo.Number, lastBlock.Hash(), blockInfo.Hash) + peerlogger.DebugDetailf("Synced chain to #%d %x %x\n", blockInfo.Number, lastBlock.Hash(), blockInfo.Hash) } p.catchingUp = false @@ -494,17 +496,17 @@ func (p *Peer) HandleInbound() { // If a parent is found send back a reply if parent != nil { - ethutil.Config.Log.Printf(ethutil.LogLevelSystem, "[PEER] Found canonical block, returning chain from: %x ", parent.Hash()) + peerlogger.DebugDetailf("Found canonical block, returning chain from: %x ", parent.Hash()) chain := p.ethereum.BlockChain().GetChainFromHash(parent.Hash(), amountOfBlocks) if len(chain) > 0 { - //ethutil.Config.Log.Debugf("[PEER] Returning %d blocks: %x ", len(chain), parent.Hash()) + //peerlogger.Debugf("Returning %d blocks: %x ", len(chain), parent.Hash()) p.QueueMessage(ethwire.NewMessage(ethwire.MsgBlockTy, chain)) } else { p.QueueMessage(ethwire.NewMessage(ethwire.MsgBlockTy, []interface{}{})) } } else { - //ethutil.Config.Log.Debugf("[PEER] Could not find a similar block") + //peerlogger.Debugf("Could not find a similar block") // If no blocks are found we send back a reply with msg not in chain // and the last hash from get chain if l > 0 { @@ -514,7 +516,7 @@ func (p *Peer) HandleInbound() { } } case ethwire.MsgNotInChainTy: - ethutil.Config.Log.Printf(ethutil.LogLevelSystem, "Not in chain: %x\n", msg.Data.Get(0).Bytes()) + peerlogger.DebugDetailf("Not in chain: %x\n", msg.Data.Get(0).Bytes()) if p.diverted == true { // If were already looking for a common parent and we get here again we need to go deeper p.blocksRequested = p.blocksRequested * 2 @@ -535,7 +537,7 @@ func (p *Peer) HandleInbound() { // Unofficial but fun nonetheless case ethwire.MsgTalkTy: - ethutil.Config.Log.Infoln("%v says: %s\n", p.conn.RemoteAddr(), msg.Data.Str()) + peerlogger.Infoln("%v says: %s\n", p.conn.RemoteAddr(), msg.Data.Str()) } } } @@ -554,7 +556,7 @@ func (p *Peer) Start() { err := p.pushHandshake() if err != nil { - ethutil.Config.Log.Debugln("Peer can't send outbound version ack", err) + peerlogger.Debugln("Peer can't send outbound version ack", err) p.Stop() @@ -628,7 +630,7 @@ func (p *Peer) handleHandshake(msg *ethwire.Msg) { p.pubkey = c.Get(5).Bytes() if p.pubkey == nil { - //ethutil.Config.Log.Debugln("Pubkey required, not supplied in handshake.") + peerlogger.Warnln("Pubkey required, not supplied in handshake.") p.Stop() return } @@ -643,13 +645,13 @@ func (p *Peer) handleHandshake(msg *ethwire.Msg) { }) if usedPub > 0 { - //ethutil.Config.Log.Debugf("Pubkey %x found more then once. Already connected to client.", p.pubkey) + peerlogger.Debugf("Pubkey %x found more then once. Already connected to client.", p.pubkey) p.Stop() return } if c.Get(0).Uint() != ProtocolVersion { - ethutil.Config.Log.Debugf("Invalid peer version. Require protocol: %d. Received: %d\n", ProtocolVersion, c.Get(0).Uint()) + peerlogger.Debugf("Invalid peer version. Require protocol: %d. Received: %d\n", ProtocolVersion, c.Get(0).Uint()) p.Stop() return } @@ -683,16 +685,16 @@ func (p *Peer) handleHandshake(msg *ethwire.Msg) { p.ethereum.PushPeer(p) p.ethereum.reactor.Post("peerList", p.ethereum.Peers()) - ethutil.Config.Log.Infof("[SERV] Added peer (%s) %d / %d\n", p.conn.RemoteAddr(), p.ethereum.Peers().Len(), p.ethereum.MaxPeers) + ethlogger.Infof("Added peer (%s) %d / %d\n", p.conn.RemoteAddr(), p.ethereum.Peers().Len(), p.ethereum.MaxPeers) // Catch up with the connected peer if !p.ethereum.IsUpToDate() { - ethutil.Config.Log.Debugln("Already syncing up with a peer; sleeping") + peerlogger.Debugln("Already syncing up with a peer; sleeping") time.Sleep(10 * time.Second) } p.SyncWithPeerToLastKnown() - ethutil.Config.Log.Debugln("[PEER]", p) + peerlogger.Debugln(p) } func (p *Peer) String() string { @@ -735,7 +737,7 @@ func (p *Peer) FindCommonParentBlock() { msgInfo := append(hashes, uint64(len(hashes))) - ethutil.Config.Log.Printf(ethutil.LogLevelSystem, "Asking for block from %x (%d total) from %s\n", p.ethereum.BlockChain().CurrentBlock.Hash(), len(hashes), p.conn.RemoteAddr().String()) + peerlogger.DebugDetailf("Asking for block from %x (%d total) from %s\n", p.ethereum.BlockChain().CurrentBlock.Hash(), len(hashes), p.conn.RemoteAddr().String()) msg := ethwire.NewMessage(ethwire.MsgGetChainTy, msgInfo) p.QueueMessage(msg) @@ -747,7 +749,7 @@ func (p *Peer) CatchupWithPeer(blockHash []byte) { msg := ethwire.NewMessage(ethwire.MsgGetChainTy, []interface{}{blockHash, uint64(50)}) p.QueueMessage(msg) - ethutil.Config.Log.Printf(ethutil.LogLevelSystem, "Requesting blockchain %x... from peer %s\n", p.ethereum.BlockChain().CurrentBlock.Hash()[:4], p.conn.RemoteAddr()) + peerlogger.DebugDetailf("Requesting blockchain %x... from peer %s\n", p.ethereum.BlockChain().CurrentBlock.Hash()[:4], p.conn.RemoteAddr()) msg = ethwire.NewMessage(ethwire.MsgGetTxsTy, []interface{}{}) p.QueueMessage(msg)