From e22e1a946ddb27c7a4a95abc71c3dcec9279b985 Mon Sep 17 00:00:00 2001 From: Martin Boehm Date: Tue, 30 Jan 2018 18:22:25 +0100 Subject: [PATCH] Use glog for logging with verbosity levels --- README.md | 5 ++++ bitcoin/bitcoinrpc.go | 20 +++++++------- bitcoin/mq.go | 12 ++++----- blockbook.go | 61 ++++++++++++++++++++++++++----------------- db/rocksdb.go | 60 ++++++++++++++++++++++++++---------------- server/https.go | 15 ++++++----- 6 files changed, 105 insertions(+), 68 deletions(-) diff --git a/README.md b/README.md index 0cd9bd5a..3be4604b 100644 --- a/README.md +++ b/README.md @@ -33,6 +33,11 @@ Install Go interface to ZeroMQ: go get github.com/pebbe/zmq4 ``` +Install glog logging: +``` +go get github.com/golang/glog +``` + Install blockbook: ``` diff --git a/bitcoin/bitcoinrpc.go b/bitcoin/bitcoinrpc.go index 402664c4..43d6dad7 100644 --- a/bitcoin/bitcoinrpc.go +++ b/bitcoin/bitcoinrpc.go @@ -5,9 +5,10 @@ import ( "encoding/hex" "encoding/json" "fmt" - "log" "net/http" "time" + + "github.com/golang/glog" ) type RPCError struct { @@ -145,7 +146,8 @@ func NewBitcoinRPC(url string, user string, password string, timeout time.Durati // GetBestBlockHash returns hash of the tip of the best-block-chain. func (b *BitcoinRPC) GetBestBlockHash() (string, error) { - log.Printf("rpc: getbestblockhash") + + glog.V(1).Info("rpc: getbestblockhash") res := resGetBestBlockHash{} req := cmdGetBestBlockHash{Method: "getbestblockhash"} @@ -162,7 +164,7 @@ func (b *BitcoinRPC) GetBestBlockHash() (string, error) { // GetBestBlockHeight returns height of the tip of the best-block-chain. func (b *BitcoinRPC) GetBestBlockHeight() (uint32, error) { - log.Printf("rpc: getblockcount") + glog.V(1).Info("rpc: getblockcount") res := resGetBlockCount{} req := cmdGetBlockCount{Method: "getblockcount"} @@ -179,7 +181,7 @@ func (b *BitcoinRPC) GetBestBlockHeight() (uint32, error) { // GetBlockHash returns hash of block in best-block-chain at given height. func (b *BitcoinRPC) GetBlockHash(height uint32) (string, error) { - log.Printf("rpc: getblockhash %v", height) + glog.V(1).Info("rpc: getblockhash ", height) res := resGetBlockHash{} req := cmdGetBlockHash{Method: "getblockhash"} @@ -197,7 +199,7 @@ func (b *BitcoinRPC) GetBlockHash(height uint32) (string, error) { // GetBlockHeader returns header of block with given hash. func (b *BitcoinRPC) GetBlockHeader(hash string) (*BlockHeader, error) { - log.Printf("rpc: getblockheader") + glog.V(1).Info("rpc: getblockheader") res := resGetBlockHeaderVerbose{} req := cmdGetBlockHeader{Method: "getblockheader"} @@ -237,7 +239,7 @@ func (b *BitcoinRPC) GetBlock(hash string) (*Block, error) { // GetBlockRaw returns block with given hash as bytes. func (b *BitcoinRPC) GetBlockRaw(hash string) ([]byte, error) { - log.Printf("rpc: getblock (verbosity=0) %v", hash) + glog.V(1).Info("rpc: getblock (verbosity=0) ", hash) res := resGetBlockRaw{} req := cmdGetBlock{Method: "getblock"} @@ -257,7 +259,7 @@ func (b *BitcoinRPC) GetBlockRaw(hash string) ([]byte, error) { // GetBlockList returns block with given hash by downloading block // transactions one by one. func (b *BitcoinRPC) GetBlockList(hash string) (*Block, error) { - log.Printf("rpc: getblock (verbosity=1) %v", hash) + glog.V(1).Info("rpc: getblock (verbosity=1) ", hash) res := resGetBlockThin{} req := cmdGetBlock{Method: "getblock"} @@ -289,7 +291,7 @@ func (b *BitcoinRPC) GetBlockList(hash string) (*Block, error) { // GetBlockFull returns block with given hash. func (b *BitcoinRPC) GetBlockFull(hash string) (*Block, error) { - log.Printf("rpc: getblock (verbosity=2) %v", hash) + glog.V(1).Info("rpc: getblock (verbosity=2) ", hash) res := resGetBlockFull{} req := cmdGetBlock{Method: "getblock"} @@ -308,7 +310,7 @@ func (b *BitcoinRPC) GetBlockFull(hash string) (*Block, error) { // GetTransaction returns a transaction by the transaction ID. func (b *BitcoinRPC) GetTransaction(txid string) (*Tx, error) { - log.Printf("rpc: getrawtransaction %v", txid) + glog.V(1).Info("rpc: getrawtransaction ", txid) res := resGetRawTransactionVerbose{} req := cmdGetRawTransaction{Method: "getrawtransaction"} diff --git a/bitcoin/mq.go b/bitcoin/mq.go index 62d46fda..75ddeafc 100644 --- a/bitcoin/mq.go +++ b/bitcoin/mq.go @@ -2,8 +2,8 @@ package bitcoin import ( "encoding/binary" - "log" + "github.com/golang/glog" zmq "github.com/pebbe/zmq4" ) @@ -38,7 +38,7 @@ func New(binding string, callback func(*MQMessage)) (*MQ, error) { socket.SetSubscribe("rawblock") socket.SetSubscribe("rawtx") socket.Connect(binding) - log.Printf("MQ listening to %s", binding) + glog.Info("MQ listening to ", binding) mq := &MQ{context, socket, true, make(chan bool)} go mq.run(callback) return mq, nil @@ -51,10 +51,10 @@ func (mq *MQ) run(callback func(*MQMessage)) { if err != nil { if zmq.AsErrno(err) == zmq.Errno(zmq.ETERM) { close(mq.finished) - log.Print("MQ loop terminated") + glog.Info("MQ loop terminated") break } - log.Printf("MQ RecvMessageBytes error %v", err) + glog.Error("MQ RecvMessageBytes error ", err) } if msg != nil && len(msg) >= 3 { sequence := uint32(0) @@ -74,7 +74,7 @@ func (mq *MQ) run(callback func(*MQMessage)) { // Shutdown stops listening to the ZeroMQ and closes the connection func (mq *MQ) Shutdown() error { - log.Printf("MQ server shutdown") + glog.Info("MQ server shutdown") if mq.isRunning { // if errors in socket.Close or context.Term, let it close ungracefully if err := mq.socket.Close(); err != nil { @@ -84,7 +84,7 @@ func (mq *MQ) Shutdown() error { return err } _, _ = <-mq.finished - log.Printf("MQ server shutdown finished") + glog.Info("MQ server shutdown finished") } return nil } diff --git a/blockbook.go b/blockbook.go index b29e207a..2d915f83 100644 --- a/blockbook.go +++ b/blockbook.go @@ -4,7 +4,6 @@ import ( "context" "encoding/hex" "flag" - "log" "os" "os/signal" "sync" @@ -15,6 +14,7 @@ import ( "blockbook/db" "blockbook/server" + "github.com/golang/glog" "github.com/pkg/profile" ) @@ -66,13 +66,16 @@ var ( func main() { flag.Parse() + // override setting for glog to log only to stderr, to match the http handler + flag.Lookup("logtostderr").Value.Set("true") + if *prof { defer profile.Start().Stop() } if *repair { if err := db.RepairRocksDB(*dbPath); err != nil { - log.Fatalf("RepairRocksDB %s: %v", *dbPath, err) + glog.Fatalf("RepairRocksDB %s: %v", *dbPath, err) } return } @@ -91,21 +94,21 @@ func main() { db, err := db.NewRocksDB(*dbPath) if err != nil { - log.Fatalf("NewRocksDB %v", err) + glog.Fatalf("NewRocksDB %v", err) } defer db.Close() if *rollbackHeight >= 0 { bestHeight, _, err := db.GetBestBlock() if err != nil { - log.Fatalf("rollbackHeight: %v", err) + glog.Fatalf("rollbackHeight: %v", err) } if uint32(*rollbackHeight) > bestHeight { - log.Printf("nothing to rollback, rollbackHeight %d, bestHeight: %d", *rollbackHeight, bestHeight) + glog.Infof("nothing to rollback, rollbackHeight %d, bestHeight: %d", *rollbackHeight, bestHeight) } else { err = db.DisconnectBlocks(uint32(*rollbackHeight), bestHeight) if err != nil { - log.Fatalf("rollbackHeight: %v", err) + glog.Fatalf("rollbackHeight: %v", err) } } return @@ -113,7 +116,7 @@ func main() { if *resync { if err := resyncIndex(rpc, db); err != nil { - log.Fatalf("resyncIndex %v", err) + glog.Fatal("resyncIndex ", err) } } @@ -121,12 +124,12 @@ func main() { if *httpServerBinding != "" { httpServer, err = server.New(*httpServerBinding, db) if err != nil { - log.Fatalf("https: %v", err) + glog.Fatalf("https: %v", err) } go func() { err = httpServer.Run() if err != nil { - log.Fatalf("https: %v", err) + glog.Fatalf("https: %v", err) } }() } @@ -135,7 +138,7 @@ func main() { if *zeroMQBinding != "" { mq, err = bitcoin.New(*zeroMQBinding, mqHandler) if err != nil { - log.Fatalf("mq: %v", err) + glog.Fatalf("mq: %v", err) } } @@ -150,10 +153,10 @@ func main() { if address != "" { script, err := bitcoin.AddressToOutputScript(address) if err != nil { - log.Fatalf("GetTransactions %v", err) + glog.Fatalf("GetTransactions %v", err) } if err = db.GetTransactions(script, height, until, printResult); err != nil { - log.Fatalf("GetTransactions %v", err) + glog.Fatalf("GetTransactions %v", err) } } else if !*resync { if err = connectBlocksParallel( @@ -164,7 +167,7 @@ func main() { *syncChunk, *syncWorkers, ); err != nil { - log.Fatalf("connectBlocksParallel %v", err) + glog.Fatalf("connectBlocksParallel %v", err) } } } @@ -176,7 +179,7 @@ func main() { func mqHandler(m *bitcoin.MQMessage) { body := hex.EncodeToString(m.Body) - log.Printf("MQ: %s-%d %s", m.Topic, m.Sequence, body) + glog.Infof("MQ: %s-%d %s", m.Topic, m.Sequence, body) } func waitForSignalAndShutdown(s *server.HttpServer, mq *bitcoin.MQ, timeout time.Duration) { @@ -188,24 +191,25 @@ func waitForSignalAndShutdown(s *server.HttpServer, mq *bitcoin.MQ, timeout time ctx, cancel := context.WithTimeout(context.Background(), timeout) defer cancel() - log.Printf("Shutdown: %v", sig) + glog.Infof("Shutdown: %v", sig) if mq != nil { if err := mq.Shutdown(); err != nil { - log.Printf("MQ.Shutdown error: %v", err) + glog.Error("MQ.Shutdown error: ", err) } } if s != nil { if err := s.Shutdown(ctx); err != nil { - log.Printf("HttpServer.Shutdown error: %v", err) + glog.Error("HttpServer.Shutdown error: ", err) } } + glog.Flush() } func printResult(txid string) error { - log.Printf("%s", txid) + glog.Info(txid) return nil } @@ -222,7 +226,7 @@ func resyncIndex(chain Blockchain, index Index) error { // If the locally indexed block is the same as the best block on the // network, we're done. if local == remote { - log.Printf("resync: synced on %d %s", localBestHeight, local) + glog.Infof("resync: synced on %d %s", localBestHeight, local) return nil } @@ -245,7 +249,7 @@ func resyncIndex(chain Blockchain, index Index) error { if forked { // find and disconnect forked blocks and then synchronize again - log.Printf("resync: local is forked") + glog.Info("resync: local is forked") var height uint32 for height = localBestHeight - 1; height >= 0; height-- { local, err = index.GetBlockHash(height) @@ -271,7 +275,7 @@ func resyncIndex(chain Blockchain, index Index) error { startHeight := uint32(0) var hash string if header != nil { - log.Printf("resync: local is behind") + glog.Info("resync: local is behind") hash = header.Next startHeight = localBestHeight } else { @@ -280,7 +284,7 @@ func resyncIndex(chain Blockchain, index Index) error { if *blockHeight > 0 { startHeight = uint32(*blockHeight) } - log.Printf("resync: genesis from block %d", startHeight) + glog.Info("resync: genesis from block ", startHeight) hash, err = chain.GetBlockHash(startHeight) if err != nil { return err @@ -295,7 +299,7 @@ func resyncIndex(chain Blockchain, index Index) error { return err } if chainBestHeight-startHeight > uint32(*syncChunk) { - log.Printf("resync: parallel sync of blocks %d-%d", startHeight, chainBestHeight) + glog.Infof("resync: parallel sync of blocks %d-%d", startHeight, chainBestHeight) err = connectBlocksParallel( chain, index, @@ -327,7 +331,9 @@ func connectBlocks( go getBlockChain(hash, chain, bch, done) + var lastRes blockResult for res := range bch { + lastRes = res if res.err != nil { return res.err } @@ -337,6 +343,10 @@ func connectBlocks( } } + if lastRes.block != nil { + glog.Infof("resync: synced on %d %s", lastRes.block.Height, lastRes.block.Hash) + } + return nil } @@ -366,7 +376,7 @@ func connectBlocksParallel( if e, ok := err.(*bitcoin.RPCError); ok && (e.Message == "Block height out of range" || e.Message == "Block not found") { break } - log.Fatalf("connectBlocksParallel %d-%d %v", low, high, err) + glog.Fatalf("connectBlocksParallel %d-%d %v", low, high, err) } } } @@ -413,6 +423,9 @@ func connectBlockChunk( if err != nil { return err } + if block.Height%1000 == 0 { + glog.Info("connected block ", block.Height, " ", block.Hash) + } } return nil diff --git a/db/rocksdb.go b/db/rocksdb.go index 4902e991..21d5f6cc 100644 --- a/db/rocksdb.go +++ b/db/rocksdb.go @@ -6,15 +6,15 @@ import ( "encoding/binary" "encoding/hex" "errors" - "log" "github.com/bsm/go-vlq" + "github.com/golang/glog" "github.com/tecbot/gorocksdb" ) func RepairRocksDB(name string) error { - log.Printf("rocksdb: repair") + glog.Infof("rocksdb: repair") opts := gorocksdb.NewDefaultOptions() return gorocksdb.RepairDb(name, opts) } @@ -39,7 +39,7 @@ var cfNames = []string{"default", "height", "outputs", "inputs"} // NewRocksDB opens an internal handle to RocksDB environment. Close // needs to be called to release it. func NewRocksDB(path string) (d *RocksDB, err error) { - log.Printf("rocksdb: open %s", path) + glog.Infof("rocksdb: open %s", path) fp := gorocksdb.NewBloomFilter(10) bbto := gorocksdb.NewDefaultBlockBasedTableOptions() @@ -73,7 +73,7 @@ func NewRocksDB(path string) (d *RocksDB, err error) { // Close releases the RocksDB environment opened in NewRocksDB. func (d *RocksDB) Close() error { - log.Printf("rocksdb: close") + glog.Infof("rocksdb: close") for _, h := range d.cfh { h.Destroy() } @@ -86,7 +86,9 @@ func (d *RocksDB) Close() error { // GetTransactions finds all input/output transactions for address specified by outputScript. // Transaction are passed to callback function. func (d *RocksDB) GetTransactions(outputScript []byte, lower uint32, higher uint32, fn func(txid string) error) (err error) { - log.Printf("rocksdb: address get %s %d-%d ", unpackOutputScript(outputScript), lower, higher) + if glog.V(1) { + glog.Infof("rocksdb: address get %s %d-%d ", unpackOutputScript(outputScript), lower, higher) + } kstart, err := packOutputKey(outputScript, lower) if err != nil { @@ -110,7 +112,9 @@ func (d *RocksDB) GetTransactions(outputScript []byte, lower uint32, higher uint if err != nil { return err } - log.Printf("rocksdb: output %s: %s", hex.EncodeToString(key), hex.EncodeToString(val)) + if glog.V(2) { + glog.Infof("rocksdb: output %s: %s", hex.EncodeToString(key), hex.EncodeToString(val)) + } for _, o := range outpoints { if err := fn(o.txid); err != nil { return err @@ -124,7 +128,9 @@ func (d *RocksDB) GetTransactions(outputScript []byte, lower uint32, higher uint return err } if input != nil { - log.Printf("rocksdb: input %s: %s", hex.EncodeToString(boutpoint), hex.EncodeToString(input)) + if glog.V(2) { + glog.Infof("rocksdb: input %s: %s", hex.EncodeToString(boutpoint), hex.EncodeToString(input)) + } inpoints, err := unpackOutputValue(input) if err != nil { return err @@ -157,11 +163,13 @@ func (d *RocksDB) writeBlock(block *bitcoin.Block, op int) error { wb := gorocksdb.NewWriteBatch() defer wb.Destroy() - switch op { - case opInsert: - log.Printf("rocksdb: insert %d %s", block.Height, block.Hash) - case opDelete: - log.Printf("rocksdb: delete %d %s", block.Height, block.Hash) + if glog.V(2) { + switch op { + case opInsert: + glog.Infof("rocksdb: insert %d %s", block.Height, block.Hash) + case opDelete: + glog.Infof("rocksdb: delete %d %s", block.Height, block.Hash) + } } if err := d.writeHeight(wb, block, op); err != nil { @@ -206,17 +214,17 @@ func (d *RocksDB) writeOutputs( for outputScript, outpoints := range records { bOutputScript, err := packOutputScript(outputScript) if err != nil { - log.Printf("rocksdb: packOutputScript warning: %v - %d %s", err, block.Height, outputScript) + glog.Warningf("rocksdb: packOutputScript: %v - %d %s", err, block.Height, outputScript) continue } key, err := packOutputKey(bOutputScript, block.Height) if err != nil { - log.Printf("rocksdb: packOutputKey warning: %v - %d %s", err, block.Height, outputScript) + glog.Warningf("rocksdb: packOutputKey: %v - %d %s", err, block.Height, outputScript) continue } val, err := packOutputValue(outpoints) if err != nil { - log.Printf("rocksdb: packOutputValue warning: %v", err) + glog.Warningf("rocksdb: packOutputValue: %v", err) continue } @@ -323,7 +331,9 @@ func (d *RocksDB) GetBestBlock() (uint32, string, error) { if it.SeekToLast(); it.Valid() { bestHeight := unpackUint(it.Key().Data()) val, err := unpackBlockValue(it.Value().Data()) - log.Printf("rocksdb: bestblock %d %s", bestHeight, val) + if glog.V(1) { + glog.Infof("rocksdb: bestblock %d %s", bestHeight, val) + } return bestHeight, val, err } return 0, "", nil @@ -375,7 +385,7 @@ func (d *RocksDB) DisconnectBlocks( lower uint32, higher uint32, ) error { - log.Printf("rocksdb: disconnecting blocks %d-%d", lower, higher) + glog.Infof("rocksdb: disconnecting blocks %d-%d", lower, higher) it := d.db.NewIteratorCF(d.ro, d.cfh[cfOutputs]) defer it.Close() outputKeys := [][]byte{} @@ -398,11 +408,13 @@ func (d *RocksDB) DisconnectBlocks( } } } - log.Printf("rocksdb: about to disconnect %d outputs from %d", len(outputKeys), totalOutputs) + glog.Infof("rocksdb: about to disconnect %d outputs from %d", len(outputKeys), totalOutputs) wb := gorocksdb.NewWriteBatch() defer wb.Destroy() for i := 0; i < len(outputKeys); i++ { - log.Printf("output %s", hex.EncodeToString(outputKeys[i])) + if glog.V(2) { + glog.Info("output ", hex.EncodeToString(outputKeys[i])) + } wb.DeleteCF(d.cfh[cfOutputs], outputKeys[i]) outpoints, err := unpackOutputValue(outputValues[i]) if err != nil { @@ -413,17 +425,21 @@ func (d *RocksDB) DisconnectBlocks( if err != nil { return err } - log.Printf("input %s", hex.EncodeToString(boutpoint)) + if glog.V(2) { + glog.Info("input ", hex.EncodeToString(boutpoint)) + } wb.DeleteCF(d.cfh[cfInputs], boutpoint) } } for height := lower; height <= higher; height++ { - log.Printf("height %d", height) + if glog.V(2) { + glog.Info("height ", height) + } wb.DeleteCF(d.cfh[cfHeight], packUint(height)) } err := d.db.Write(d.wo, wb) if err == nil { - log.Printf("rocksdb: blocks %d-%d disconnected", lower, higher) + glog.Infof("rocksdb: blocks %d-%d disconnected", lower, higher) } return err } diff --git a/server/https.go b/server/https.go index 468af285..82512ec5 100644 --- a/server/https.go +++ b/server/https.go @@ -6,11 +6,12 @@ import ( "context" "encoding/json" "fmt" - "log" "net/http" "os" "strconv" + "github.com/golang/glog" + "github.com/gorilla/handlers" "github.com/gorilla/mux" ) @@ -37,7 +38,7 @@ func New(httpServerBinding string, db *db.RocksDB) (*HttpServer, error) { r.HandleFunc("/transactions/{address}/{lower}/{higher}", s.transactions) var h http.Handler = r - h = handlers.LoggingHandler(os.Stdout, h) + h = handlers.LoggingHandler(os.Stderr, h) https.Handler = h return s, nil @@ -45,25 +46,25 @@ func New(httpServerBinding string, db *db.RocksDB) (*HttpServer, error) { // Run starts the server func (s *HttpServer) Run() error { - log.Printf("http server starting to listen on %s", s.https.Addr) + glog.Infof("http server starting to listen on %s", s.https.Addr) return s.https.ListenAndServe() } // Close closes the server func (s *HttpServer) Close() error { - log.Printf("http server closing") + glog.Infof("http server closing") return s.https.Close() } // Shutdown shuts down the server func (s *HttpServer) Shutdown(ctx context.Context) error { - log.Printf("http server shutdown") + glog.Infof("http server shutdown") return s.https.Shutdown(ctx) } func respondError(w http.ResponseWriter, err error, context string) { w.WriteHeader(http.StatusBadRequest) - log.Printf("http server %s error: %v", context, err) + glog.Errorf("http server %s error: %v", context, err) } func respondHashData(w http.ResponseWriter, hash string) { @@ -84,7 +85,7 @@ func (s *HttpServer) info(w http.ResponseWriter, r *http.Request) { height, hash, err := s.db.GetBestBlock() if err != nil { - log.Printf("https info: %v", err) + glog.Errorf("https info: %v", err) } json.NewEncoder(w).Encode(info{